Svn: 6735 - 2 SB2 class players connected. Output of netstat after the event - shows that multiple tcp sessions are left open for a given player. Problem player 192.168.1.102 has frozen its Rss screen and is not responding to IR commands at this time. It does not show up on web page as an attached client. [slimserver@vig ~]$ netstat Active Internet connections (w/o servers) Proto Recv-Q Send-Q Local Address Foreign Address State tcp 0 0 Vig.lan:3483 192.168.1.101:31695 ESTABLISHED tcp 0 0 Vig.lan:3483 192.168.1.101:31694 ESTABLISHED tcp 0 0 Vig.lan:3483 192.168.1.101:31693 ESTABLISHED tcp 0 0 Vig.lan:3483 192.168.1.101:31692 ESTABLISHED tcp 0 0 Vig.lan:3483 192.168.1.102:35164 ESTABLISHED tcp 0 0 Vig.lan:3483 192.168.1.102:35166 ESTABLISHED tcp 0 0 Vig.lan:9000 Mesh.lan:1150 ESTABLISHED tcp 0 314 Vig.lan:telnet Mesh.lan:1188 ESTABLISHED tcp 0 0 Vig.lan:microsoft-ds Mesh.lan:1072 ESTABLISHED Output from --d_slimproto --d_slimproto_v running during this time: Normal activity - due to date time screensaver on player 101, Rss on 102 (which does not generate slimproto debug): 2006-03-30 15:00:00.0017 sending squeezebox frame: grfe, length: 1284 2006-03-30 15:01:00.0025 sending squeezebox frame: grfe, length: 1284 2006-03-30 15:02:00.0024 sending squeezebox frame: grfe, length: 1284 2006-03-30 15:03:00.0023 sending squeezebox frame: grfe, length: 1284 reconnect of player 101 (probably following wireless blip): 2006-03-30 15:43:10.0092 Slimproto accepted connection from: [192.168.1.101:31695] 2006-03-30 15:43:10.0099 Setting timer in 5 seconds to close bogus connection 2006-03-30 15:43:10.0110 Slimproto client readable: 192.168.1.101:31695 2006-03-30 15:43:10.0116 state: OP, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.0120 attempting to read 4 bytes 2006-03-30 15:43:10.0123 Got 4 bytes from client, 0 remaining 2006-03-30 15:43:10.0127 got op: HELO 2006-03-30 15:43:10.0130 new state: LENGTH 2006-03-30 15:43:10.0134 state: LENGTH, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.0137 attempting to read 4 bytes 2006-03-30 15:43:10.0141 Got 4 bytes from client, 0 remaining 2006-03-30 15:43:10.0145 new state: DATA 2006-03-30 15:43:10.0149 state: DATA, framelen: 18, inbuflen: 0 2006-03-30 15:43:10.0153 attempting to read 18 bytes 2006-03-30 15:43:10.0156 Got 18 bytes from client, 0 remaining 2006-03-30 15:43:10.0164 _hello_handler: Killing bogus player timer. 2006-03-30 15:43:10.0171 Squeezebox says hello. Deviceid: 4 revision: 35 mac: 00:04:20:05:a4:00 bitmapped: 32768 reconnect: 0 wlan_channellist: 0000 2006-03-30 15:43:10.0176 Squeezebox also says. bytes_received: 0 2006-03-30 15:43:10.0181 hello from existing client: 00:04:20:05:a4:00 on ipport: 192.168.1.101:31695 2006-03-30 15:43:10.0191 *************stream called: q paused: format: url: 2006-03-30 15:43:10.0198 Backtrace: frame 0: Slim::Player::Squeezebox::stream (/usr/local/slimserver/Slim/Player/Squeezebox.pm line 197) frame 1: Slim::Player::Squeezebox::stop (/usr/local/slimserver/Slim/Player/Squeezebox2.pm line 634) frame 2: Slim::Player::Squeezebox2::stop (/usr/local/slimserver/Slim/Player/Squeezebox.pm line 82) frame 3: Slim::Player::Squeezebox::reconnect (/usr/local/slimserver/Slim/Networking/Slimproto.pm line 706) frame 4: Slim::Networking::Slimproto::_hello_handler (/usr/local/slimserver/Slim/Networking/Slimproto.pm line 305) frame 5: Slim::Networking::Slimproto::client_readable (/usr/local/slimserver/Slim/Networking/Select.pm line 132) frame 6: Slim::Networking::Select::select (/usr/local/slimserver/slimserver.pl line 631) frame 7: main::idle (/usr/local/slimserver/slimserver.pl line 577) frame 8: main::main (/usr/local/slimserver/slimserver.pl line 1221) 2006-03-30 15:43:10.0204 starting with decoder with format: m autostart: 0 threshold: 255 samplesize: ? samplerate: ? endian: ? channels: ? 2006-03-30 15:43:10.0208 flags: 0 2006-03-30 15:43:10.0212 sending strm frame of length: 76 request string: GET /stream.mp3?player=00:04:20:05:a4:00 HTTP/1.0 2006-03-30 15:43:10.0216 sending squeezebox frame: strm, length: 76 2006-03-30 15:43:10.0226 sending squeezebox frame: grfb, length: 2 2006-03-30 15:43:10.0253 sending squeezebox frame: grfe, length: 1284 2006-03-30 15:43:10.0265 sending squeezebox frame: visu, length: 2 2006-03-30 15:43:10.0286 sending squeezebox frame: audg, length: 18 2006-03-30 15:43:10.0295 new state: OP 2006-03-30 15:43:10.0301 state: OP, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.0305 attempting to read 4 bytes 2006-03-30 15:43:10.0309 Got 4 bytes from client, 0 remaining 2006-03-30 15:43:10.0313 got op: STAT 2006-03-30 15:43:10.0318 new state: LENGTH 2006-03-30 15:43:10.0322 state: LENGTH, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.0326 attempting to read 4 bytes 2006-03-30 15:43:10.0330 Got 4 bytes from client, 0 remaining 2006-03-30 15:43:10.0334 new state: DATA 2006-03-30 15:43:10.0338 state: DATA, framelen: 41, inbuflen: 0 2006-03-30 15:43:10.0342 attempting to read 41 bytes 2006-03-30 15:43:10.0348 Got 41 bytes from client, 0 remaining 2006-03-30 15:43:10.0356 00:04:20:05:a4:00 Squeezebox stream status: fullness: 0 (0%) bytes_received 0 2006-03-30 15:43:10.0361 output size: 3528000 output fullness: 3504960 elapsed seconds: 0 2006-03-30 15:43:10.0366 new state: OP 2006-03-30 15:43:10.0370 state: OP, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.0374 attempting to read 4 bytes 2006-03-30 15:43:10.0378 Got 4 bytes from client, 0 remaining 2006-03-30 15:43:10.0382 got op: STAT 2006-03-30 15:43:10.0385 new state: LENGTH 2006-03-30 15:43:10.0389 state: LENGTH, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.0393 attempting to read 4 bytes 2006-03-30 15:43:10.0397 Got 4 bytes from client, 0 remaining 2006-03-30 15:43:10.0401 new state: DATA 2006-03-30 15:43:10.0405 state: DATA, framelen: 41, inbuflen: 0 2006-03-30 15:43:10.0409 attempting to read 41 bytes 2006-03-30 15:43:10.0413 Got 41 bytes from client, 0 remaining 2006-03-30 15:43:10.0421 00:04:20:05:a4:00 Squeezebox stream status: fullness: 0 (0%) bytes_received 0 2006-03-30 15:43:10.0426 output size: 3528000 output fullness: 3504960 elapsed seconds: 0 2006-03-30 15:43:10.0431 new state: OP 2006-03-30 15:43:10.0435 state: OP, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.0439 attempting to read 4 bytes 2006-03-30 15:43:10.0443 Got 4 bytes from client, 0 remaining 2006-03-30 15:43:10.0447 got op: STAT 2006-03-30 15:43:10.0451 new state: LENGTH 2006-03-30 15:43:10.0455 state: LENGTH, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.0459 attempting to read 4 bytes 2006-03-30 15:43:10.0463 Got 4 bytes from client, 0 remaining 2006-03-30 15:43:10.0467 new state: DATA 2006-03-30 15:43:10.0471 state: DATA, framelen: 41, inbuflen: 0 2006-03-30 15:43:10.0475 attempting to read 41 bytes 2006-03-30 15:43:10.0479 Got 41 bytes from client, 0 remaining 2006-03-30 15:43:10.0488 00:04:20:05:a4:00 Squeezebox stream status: fullness: 0 (0%) bytes_received 0 2006-03-30 15:43:10.0493 output size: 3528000 output fullness: 3504960 elapsed seconds: 0 2006-03-30 15:43:10.0498 new state: OP 2006-03-30 15:43:10.0502 state: OP, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.0506 attempting to read 4 bytes 2006-03-30 15:43:10.0511 Got 4 bytes from client, 0 remaining 2006-03-30 15:43:10.0515 got op: STAT 2006-03-30 15:43:10.0518 new state: LENGTH 2006-03-30 15:43:10.0522 state: LENGTH, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.0526 attempting to read 4 bytes 2006-03-30 15:43:10.0530 Got 4 bytes from client, 0 remaining 2006-03-30 15:43:10.0535 new state: DATA 2006-03-30 15:43:10.0539 state: DATA, framelen: 41, inbuflen: 0 2006-03-30 15:43:10.0543 attempting to read 41 bytes 2006-03-30 15:43:10.0547 Got 41 bytes from client, 0 remaining 2006-03-30 15:43:10.0555 00:04:20:05:a4:00 Squeezebox stream status: fullness: 0 (0%) bytes_received 0 2006-03-30 15:43:10.0560 output size: 3528000 output fullness: 3504960 elapsed seconds: 0 2006-03-30 15:43:10.0565 new state: OP 2006-03-30 15:43:10.0570 state: OP, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.0574 attempting to read 4 bytes 2006-03-30 15:43:10.0577 no more to read. reconnect from client 102 - note this is on port 35166: 2006-03-30 15:43:10.3113 Slimproto accepted connection from: [192.168.1.102:35166] 2006-03-30 15:43:10.3120 Setting timer in 5 seconds to close bogus connection 2006-03-30 15:43:10.3130 Slimproto client readable: 192.168.1.102:35166 2006-03-30 15:43:10.3138 state: OP, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.3142 attempting to read 4 bytes 2006-03-30 15:43:10.3146 Got 4 bytes from client, 0 remaining 2006-03-30 15:43:10.3151 got op: HELO 2006-03-30 15:43:10.3154 new state: LENGTH 2006-03-30 15:43:10.3158 state: LENGTH, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.3162 attempting to read 4 bytes 2006-03-30 15:43:10.3166 Got 4 bytes from client, 0 remaining 2006-03-30 15:43:10.3171 new state: DATA 2006-03-30 15:43:10.3175 state: DATA, framelen: 18, inbuflen: 0 2006-03-30 15:43:10.3180 attempting to read 18 bytes 2006-03-30 15:43:10.3184 Got 18 bytes from client, 0 remaining 2006-03-30 15:43:10.3193 _hello_handler: Killing bogus player timer. 2006-03-30 15:43:10.3201 Squeezebox says hello. Deviceid: 4 revision: 35 mac: 00:04:20:06:08:c7 bitmapped: 32768 reconnect: 0 wlan_channellist: 0000 2006-03-30 15:43:10.3205 Squeezebox also says. bytes_received: 0 2006-03-30 15:43:10.3211 hello from existing client: 00:04:20:06:08:c7 on ipport: 192.168.1.102:35166 2006-03-30 15:43:10.3221 *************stream called: q paused: format: url: 2006-03-30 15:43:10.3228 Backtrace: frame 0: Slim::Player::Squeezebox::stream (/usr/local/slimserver/Slim/Player/Squeezebox.pm line 197) frame 1: Slim::Player::Squeezebox::stop (/usr/local/slimserver/Slim/Player/Squeezebox2.pm line 634) frame 2: Slim::Player::Squeezebox2::stop (/usr/local/slimserver/Slim/Player/Squeezebox.pm line 82) frame 3: Slim::Player::Squeezebox::reconnect (/usr/local/slimserver/Slim/Networking/Slimproto.pm line 706) frame 4: Slim::Networking::Slimproto::_hello_handler (/usr/local/slimserver/Slim/Networking/Slimproto.pm line 305) frame 5: Slim::Networking::Slimproto::client_readable (/usr/local/slimserver/Slim/Networking/Select.pm line 132) frame 6: Slim::Networking::Select::select (/usr/local/slimserver/slimserver.pl line 631) frame 7: main::idle (/usr/local/slimserver/slimserver.pl line 577) frame 8: main::main (/usr/local/slimserver/slimserver.pl line 1221) 2006-03-30 15:43:10.3234 starting with decoder with format: m autostart: 0 threshold: 255 samplesize: ? samplerate: ? endian: ? channels: ? 2006-03-30 15:43:10.3239 flags: 0 2006-03-30 15:43:10.3243 sending strm frame of length: 76 request string: GET /stream.mp3?player=00:04:20:06:08:c7 HTTP/1.0 2006-03-30 15:43:10.3248 sending squeezebox frame: strm, length: 76 2006-03-30 15:43:10.3261 sending squeezebox frame: grfb, length: 2 2006-03-30 15:43:10.3293 sending squeezebox frame: visu, length: 2 2006-03-30 15:43:10.3314 sending squeezebox frame: audg, length: 18 2006-03-30 15:43:10.3324 new state: OP 2006-03-30 15:43:10.3330 state: OP, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.3334 attempting to read 4 bytes 2006-03-30 15:43:10.3338 Got 4 bytes from client, 0 remaining 2006-03-30 15:43:10.3344 got op: STAT 2006-03-30 15:43:10.3349 new state: LENGTH 2006-03-30 15:43:10.3353 state: LENGTH, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.3357 attempting to read 4 bytes 2006-03-30 15:43:10.3361 Got 4 bytes from client, 0 remaining 2006-03-30 15:43:10.3366 new state: DATA 2006-03-30 15:43:10.3371 state: DATA, framelen: 41, inbuflen: 0 2006-03-30 15:43:10.3375 attempting to read 41 bytes 2006-03-30 15:43:10.3379 Got 41 bytes from client, 0 remaining 2006-03-30 15:43:10.3388 00:04:20:06:08:c7 Squeezebox stream status: fullness: 0 (0%) bytes_received 0 2006-03-30 15:43:10.3394 output size: 3528000 output fullness: 484736 elapsed seconds: 0 2006-03-30 15:43:10.3398 new state: OP 2006-03-30 15:43:10.3403 state: OP, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.3407 attempting to read 4 bytes 2006-03-30 15:43:10.3412 Got 4 bytes from client, 0 remaining 2006-03-30 15:43:10.3416 got op: STAT 2006-03-30 15:43:10.3419 new state: LENGTH 2006-03-30 15:43:10.3423 state: LENGTH, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.3427 attempting to read 4 bytes 2006-03-30 15:43:10.3432 Got 4 bytes from client, 0 remaining 2006-03-30 15:43:10.3436 new state: DATA 2006-03-30 15:43:10.3440 state: DATA, framelen: 41, inbuflen: 0 2006-03-30 15:43:10.3444 attempting to read 41 bytes 2006-03-30 15:43:10.3448 Got 41 bytes from client, 0 remaining 2006-03-30 15:43:10.3457 00:04:20:06:08:c7 Squeezebox stream status: fullness: 0 (0%) bytes_received 0 2006-03-30 15:43:10.3462 output size: 3528000 output fullness: 484736 elapsed seconds: 0 2006-03-30 15:43:10.3467 new state: OP 2006-03-30 15:43:10.3471 state: OP, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.3475 attempting to read 4 bytes 2006-03-30 15:43:10.3479 Got 4 bytes from client, 0 remaining 2006-03-30 15:43:10.3483 got op: STAT 2006-03-30 15:43:10.3487 new state: LENGTH 2006-03-30 15:43:10.3491 state: LENGTH, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.3496 attempting to read 4 bytes 2006-03-30 15:43:10.3500 Got 4 bytes from client, 0 remaining 2006-03-30 15:43:10.3504 new state: DATA 2006-03-30 15:43:10.3509 state: DATA, framelen: 41, inbuflen: 0 2006-03-30 15:43:10.3513 attempting to read 41 bytes 2006-03-30 15:43:10.3517 Got 41 bytes from client, 0 remaining 2006-03-30 15:43:10.3525 00:04:20:06:08:c7 Squeezebox stream status: fullness: 0 (0%) bytes_received 0 2006-03-30 15:43:10.3531 output size: 3528000 output fullness: 484736 elapsed seconds: 0 2006-03-30 15:43:10.3535 new state: OP 2006-03-30 15:43:10.3540 state: OP, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.3544 attempting to read 4 bytes 2006-03-30 15:43:10.3548 Got 4 bytes from client, 0 remaining 2006-03-30 15:43:10.3552 got op: STAT 2006-03-30 15:43:10.3555 new state: LENGTH 2006-03-30 15:43:10.3559 state: LENGTH, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.3563 attempting to read 4 bytes 2006-03-30 15:43:10.3567 Got 4 bytes from client, 0 remaining 2006-03-30 15:43:10.3572 new state: DATA 2006-03-30 15:43:10.3576 state: DATA, framelen: 41, inbuflen: 0 2006-03-30 15:43:10.3580 attempting to read 41 bytes 2006-03-30 15:43:10.3584 Got 41 bytes from client, 0 remaining 2006-03-30 15:43:10.3592 00:04:20:06:08:c7 Squeezebox stream status: fullness: 0 (0%) bytes_received 0 2006-03-30 15:43:10.3598 output size: 3528000 output fullness: 484736 elapsed seconds: 0 2006-03-30 15:43:10.3602 new state: OP 2006-03-30 15:43:10.3607 state: OP, framelen: 0, inbuflen: 0 2006-03-30 15:43:10.3611 attempting to read 4 bytes 2006-03-30 15:43:10.3615 no more to read. ####################################################################### Problem ####################################################################### The following shows client 102 being disconnected due to the *old* socket (35165) being closed. Note that this is saying that slimproto_close is being called which will forget the player after 5 minutes. 2006-03-30 15:43:15.7396 Slimproto client readable: 192.168.1.102:35165 2006-03-30 15:43:15.7402 Slimproto connection closed by peer in readable. 2006-03-30 15:43:15.7406 Slimproto connection closed 2006-03-30 15:44:00.0017 sending squeezebox frame: grfe, length: 1284 2006-03-30 15:45:00.0026 sending squeezebox frame: grfe, length: 1284 2006-03-30 15:46:00.0025 sending squeezebox frame: grfe, length: 1284 2006-03-30 15:47:00.0024 sending squeezebox frame: grfe, length: 1284