Bugzilla – Bug 3397
AsyncHTTP somehow broken?
Last modified: 2008-09-15 14:38:25 UTC
My Biography/AlbumReview plugins do not work anymore with 6.2.2. There must have been a change in the http handling somewhere as they're always getting a "bad request" answer (-d_http -d_http_async -d_plugins): 2006-05-07 07:55:11.7757 AsyncHTTP: Connecting to www.allmusic.com 2006-05-07 07:55:12.4141 AsyncHTTP: Sending request: POST /cg/amg.dll HTTP/1.1 Connection: close Host: www.allmusic.com Icy-Metadata: 1 User-Agent: iTunes/4.7.1 (Windows; N; Windows XP; 586; EN; cp1252) SlimServer/6.2.2/7135 Cache-Control: no-cache Content-Type: application/x-www-form-urlencoded Accept: */* SQL=UP&OPT1=2&submit=Go&P=amg: 2006-05-07 07:55:12.4156 End request: keepAlive: [1] - waiting for next request on connection = Keep-Alive, TE 2006-05-07 07:55:12.5480 AsyncHTTP: Headers read. code: 400 status: Bad Request 2006-05-07 07:55:12.5486 SimpleAsyncHTTP: status for http://www.allmusic.com/cg/amg.dll is Bad Request - fileno: 19 2006-05-07 07:55:12.5494 AsyncHTTP: Body read for fileno: 19 2006-05-07 07:55:12.5501 AlbumReview: nothing found? 2006-05-07 07:55:12.5666 generating from plugins/AlbumReview/index.html 2006-05-07 07:55:12.5878 SimpleAsyncHTTP(http://www.allmusic.com/cg/amg.dll) destroy called. 2006-05-07 07:55:12.6309 More to send to 127.0.0.1 2006-05-07 07:55:12.6575 No more messages to send to 127.0.0.1 2006-05-07 07:55:12.6589 No segment to send to 127.0.0.1, waiting for next request.. 6.3 is fine - but the changes rather major :-(
6.2.2's async code is unchanged from 6.2.1 I believe. 6.3 has the major changes. From your debug log I notice the request looks malformed in that there is no blank line between the headers and POST body. What's the log output from 6.3 look like?
I know that there have been major changes in 6.3. That's why I wasn't sure where to look for the problem. So here's my 6.3 output: 2006-05-08 23:08:31.1388 HTTP parameter player = 6e:ef:54:e9:02:b0 2006-05-08 23:08:31.1423 processURL Clients: 192.168.203.1:2509 2006-05-08 23:08:31.1430 Generating response for (htm, text/html) plugins/AlbumReview/index.html 2006-05-08 23:08:31.1434 generating from include.html 2006-05-08 23:08:31.1816 AlbumReview (get artist's name): 'Genesis', album: 'Platinum Collection' 2006-05-08 23:08:31.1889 AlbumReview (cache): need to look online for Genesis/Platinum Collection... 2006-05-08 23:08:31.2033 AlbumReview (get artist's name): 'Genesis', album: 'Platinum Collection' 2006-05-08 23:08:31.2042 SimpleAsyncHTTP: POSTing http://www.allmusic.com/cg/amg.dll 2006-05-08 23:08:31.2049 AsyncHTTP: Starting async DNS lookup for [www.allmusic.com] 2006-05-08 23:08:31.2104 End request: keepAlive: [1] - waiting for next request on connection = Keep-Alive, TE 2006-05-08 23:08:32.2891 AsyncHTTP: Resolved www.allmusic.com to [166.90.203.178] 2006-05-08 23:08:32.2898 AsyncHTTP: Connecting to www.allmusic.com:80 2006-05-08 23:08:32.5968 AsyncHTTP: connected, ready to write request 2006-05-08 23:08:32.5979 AsyncHTTP: Sending request: POST /cg/amg.dll HTTP/1.1 Connection: close Icy-Metadata: 1 User-Agent: iTunes/4.7.1 (Windows; N; Windows XP; 586; EN; cp1252) SlimServer/6.3.0/trunk Cache-Control: no-cache Content-Type: application/x-www-form-urlencoded Accept: */* Host: www.allmusic.com Content-Length: 48 SQL=PLATINUM%20COLLECTION&OPT1=2&submit=Go&P=amg 2006-05-08 23:08:32.6008 AsyncHTTP: State: headers-read 2006-05-08 23:08:39.6640 AsyncHTTP: Headers read. code: 200 status: OK 2006-05-08 23:08:39.6647 AsyncHTTP: State: headers-done 2006-05-08 23:08:39.6652 SimpleAsyncHTTP: status for http://www.allmusic.com/cg/amg.dll is OK - fileno: 14 2006-05-08 23:08:39.6657 AsyncHTTP: State: body-read 2006-05-08 23:08:41.0391 AsyncHTTP: Body read for fileno: 14 2006-05-08 23:08:41.0412 AsyncHTTP: State: body-done 2006-05-08 23:08:41.0552 AlbumReview: nothing found? There is a blank line in here...
Can you also post 6.2.1's output?
6.2.1 output: 2006-05-08 23:21:00.8614 AsyncHTTP: Resolved www.allmusic.com to [166.90.203.189] 2006-05-08 23:21:00.8618 AsyncHTTP: Connecting to www.allmusic.com:80 2006-05-08 23:21:01.1053 Prevent Standby plugin: client 192.168.203.1 in playmode play 2006-05-08 23:21:01.1056 Prevent Standby plugin: setting thread execution state 2006-05-08 23:21:01.1057 Prevent Standby plugin: starting timer 2006-05-08 23:21:01.1081 Accepted connection 8 from 127.0.0.1 2006-05-08 23:21:01.1085 AsyncHTTP: connected, ready to write request 2006-05-08 23:21:01.1088 AsyncHTTP: Sending request: POST /cg/amg.dll HTTP/1.1 Connection: close Icy-Metadata: 1 User-Agent: iTunes/4.7.1 (Windows; N; Windows XP; 586; EN; cp1252) SlimServer/6.3.0/7317 Cache-Control: no-cache Content-Type: application/x-www-form-urlencoded Accept: */* Host: www.allmusic.com Content-Length: 42 SQL=PETER%20GABRIEL&OPT1=1&submit=Go&P=amg 2006-05-08 23:21:01.1095 AsyncHTTP: State: headers-read 2006-05-08 23:21:01.1107 reading request... 2006-05-08 23:21:01.1112 HTTP request: from 127.0.0.1 (HTTP::Daemon::ClientConn=GLOB(0x4a0b28c)) for GET HTTP/1.1 /html/ images/nav_spacer.gif 2006-05-08 23:21:01.1127 processURL Clients: 192.168.203.1:2787 2006-05-08 23:21:01.1130 Generating response for (gif, image/gif) html/images/nav_spacer.gif 2006-05-08 23:21:01.1135 generating from html/images/nav_spacer.gif 2006-05-08 23:21:01.1136 reading http file for (Default html/images/nav_spacer.gif) 2006-05-08 23:21:01.1138 Checking for C:\temp\SlimServer for Windows\server\HTML\Default\html\images\nav_spacer.gif. 2006-05-08 23:21:01.1149 generating from html/images/nav_spacer.gif 2006-05-08 23:21:01.1150 reading http file for (Default html/images/nav_spacer.gif) 2006-05-08 23:21:01.1152 Checking for C:\temp\SlimServer for Windows\server\HTML\Default\html\images\nav_spacer.gif. 2006-05-08 23:21:01.1167 End request: keepAlive: [1] - waiting for next request on connection = Keep-Alive, TE 2006-05-08 23:21:01.1174 Accepted connection 9 from 127.0.0.1 2006-05-08 23:21:01.1187 reading request... 2006-05-08 23:21:01.1189 HTTP request: from 127.0.0.1 (HTTP::Daemon::ClientConn=GLOB(0x4992df0)) for GET HTTP/1.1 /html/ images/player_standby.gif 2006-05-08 23:21:01.1204 processURL Clients: 192.168.203.1:2787 2006-05-08 23:21:01.1206 Generating response for (gif, image/gif) html/images/player_standby.gif 2006-05-08 23:21:01.1211 generating from html/images/player_standby.gif 2006-05-08 23:21:01.1212 reading http file for (Default html/images/player_standby.gif) 2006-05-08 23:21:01.1214 Checking for C:\temp\SlimServer for Windows\server\HTML\Default\html\images\player_standby.gif. 2006-05-08 23:21:01.1223 generating from html/images/player_standby.gif 2006-05-08 23:21:01.1225 reading http file for (Default html/images/player_standby.gif) 2006-05-08 23:21:01.1226 Checking for C:\temp\SlimServer for Windows\server\HTML\Default\html\images\player_standby.gif. 2006-05-08 23:21:01.1239 End request: keepAlive: [1] - waiting for next request on connection = Keep-Alive, TE 2006-05-08 23:21:01.1257 No more messages to send to 127.0.0.1 2006-05-08 23:21:01.2824 No more messages to send to 127.0.0.1 2006-05-08 23:21:01.3300 No segment to send to 127.0.0.1, waiting for next request.. 2006-05-08 23:21:01.3309 No segment to send to 127.0.0.1, waiting for next request.. 2006-05-08 23:21:02.8549 AsyncHTTP: Headers read. code: 200 status: OK 2006-05-08 23:21:02.8554 AsyncHTTP: State: headers-done 2006-05-08 23:21:02.8555 SimpleAsyncHTTP: status for http://www.allmusic.com/cg/amg.dll is OK - fileno: 16 2006-05-08 23:21:02.8558 AsyncHTTP: State: body-read 2006-05-08 23:21:04.2252 AsyncHTTP: Body read for fileno: 16 2006-05-08 23:21:04.2255 AsyncHTTP: State: body-done Thanks!
There was actually a "fix" I made to AsyncHTTP that introduced this bug. Sorry about that. Can you try this attached file and see if it fixes the problem? The change where this happened is at http://svn.slimdevices.com/branches/BRANCH_6_2_x/server/Slim/Networking/AsyncHTTP.pm?rev=7016&r1=4752&r2=7016
Created attachment 1231 [details] Fixed version of AsyncHTTP
Thanks, this is looking good!
Fixed, will be in 6.3.
You checked it in to 6.2.x - will there be a nightly 6.2.x build?
Sorry no, we figured this bug wasn't serious enough to warrant a new 6.2 release.
This bug fix is now part of a released version, and so has been marked closed. If you are still experiencing this problem, please reopen the bug.