OpenHome Forum / OpenHome / Media v / Bad Request

 
Thread Rating:
  • 0 Votes - 0 Average
  • 1
  • 2
  • 3
  • 4
  • 5
Bad Request
02-10-2013, 01:54 PM
Post: #1
PeteManchester Offline
Member
***
 		Posts: 58
Joined: Mar 2013
Reputation: 0
Bad Request
Hi,

I've got my Java MediaPlayer working well and am now testing against different control points.

I seem to have an issue with one control point, the control point can discover my media renderer but when I select it, it comes up with a message 'Searching for...'

I set the OpenHome log levels to 'all' in my renderer and can see a message 'Bad Request', is there any way to tell what the request is, I tried using WireShark but still couldn't locate the problem..

Below is an extract of the log from one Bad Request to anther..

Thanks,

Pete.


Code:
2013-10-02 14:36:36,095 [Thread-31] INFO  [org.rpi.main.OpenHomeLogger] PropertyWriter, http error 400
2013-10-02 14:36:36,095 [Thread-31] INFO  [org.rpi.main.OpenHomeLogger] Bad Request
2013-10-02 14:36:36,095 [Thread-31] INFO  [org.rpi.main.OpenHomeLogger]

2013-10-02 14:36:36,095 [Thread-31] INFO  [org.rpi.main.OpenHomeLogger] >Timer::Cancel()

2013-10-02 14:36:36,095 [Thread-31] INFO  [org.rpi.main.OpenHomeLogger] <Timer::Cancel()

2013-10-02 14:36:36,095 [Thread-31] INFO  [org.rpi.main.OpenHomeLogger] OpenHome/Network.cpp:184:
2013-10-02 14:36:36,095 [Thread-31] INFO  [org.rpi.main.OpenHomeLogger] Socket::Close H = 489667016

2013-10-02 14:36:36,125 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] OpenHome/Network.cpp:268:
2013-10-02 14:36:36,125 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <Socket::Receive H = 489666992, BC = 125

2013-10-02 14:36:36,125 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] OpenHome/Network.cpp:454:
2013-10-02 14:36:36,125 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <SocketTcp::Read

2013-10-02 14:36:36,125 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >Timer::Cancel()

2013-10-02 14:36:36,125 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >TimerManager::HeadChanged()

2013-10-02 14:36:36,125 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <TimerManager::HeadChanged() retrigger timer

2013-10-02 14:36:36,125 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <Timer::Cancel()

2013-10-02 14:36:36,125 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] HTTP Read Response  
2013-10-02 14:36:36,125 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] HTTP/1.1 400 Bad Request
2013-10-02 14:36:36,125 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger]

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >Timer::FireIn(5000)

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >Timer::FireAt(140420)

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >TimerManager::HeadChanged()

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <TimerManager::HeadChanged() retrigger timer

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <Timer::FireAt(140420)

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <Timer::FireIn(5000)

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >Timer::Cancel()

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >TimerManager::HeadChanged()

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <TimerManager::HeadChanged() retrigger timer

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <Timer::Cancel()

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] HTTP Read Response  
2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] Accept-Ranges: bytes
2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger]

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >Timer::FireIn(5000)

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >Timer::FireAt(140420)

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >TimerManager::HeadChanged()

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <TimerManager::HeadChanged() retrigger timer

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <Timer::FireAt(140420)

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <Timer::FireIn(5000)

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >Timer::Cancel()

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >TimerManager::HeadChanged()

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <TimerManager::HeadChanged() retrigger timer

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <Timer::Cancel()

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] HTTP Read Response  
2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] Content-Length: 0
2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger]

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >Timer::FireIn(5000)

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >Timer::FireAt(140420)

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >TimerManager::HeadChanged()

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <TimerManager::HeadChanged() retrigger timer

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <Timer::FireAt(140420)

2013-10-02 14:36:36,126 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <Timer::FireIn(5000)

2013-10-02 14:36:36,133 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >Timer::Cancel()

2013-10-02 14:36:36,133 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >TimerManager::HeadChanged()

2013-10-02 14:36:36,133 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <TimerManager::HeadChanged() retrigger timer

2013-10-02 14:36:36,133 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <Timer::Cancel()

2013-10-02 14:36:36,133 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] HTTP Read Response  
2013-10-02 14:36:36,133 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] Connection: close
2013-10-02 14:36:36,133 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger]

2013-10-02 14:36:36,133 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >Timer::FireIn(5000)

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >Timer::FireAt(140428)

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >TimerManager::HeadChanged()

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <TimerManager::HeadChanged() retrigger timer

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <Timer::FireAt(140428)

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <Timer::FireIn(5000)

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >Timer::Cancel()

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >TimerManager::HeadChanged()

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <TimerManager::HeadChanged() retrigger timer

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <Timer::Cancel()

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] HTTP Read Response  
2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] Date: Wed, 02 Oct 2013 13:36:45 GMT
2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger]

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >Timer::FireIn(5000)

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >Timer::FireAt(140428)

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >TimerManager::HeadChanged()

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <TimerManager::HeadChanged() retrigger timer

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <Timer::FireAt(140428)

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <Timer::FireIn(5000)

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >Timer::Cancel()

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] >TimerManager::HeadChanged()

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <TimerManager::HeadChanged() retrigger timer

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] <Timer::Cancel()

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] HTTP Read Response  
2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger]

2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] PropertyWriter, http error 400
2013-10-02 14:36:36,134 [Thread-33] INFO  [org.rpi.main.OpenHomeLogger] Bad Request
Find all posts by this user
02-10-2013, 03:02 PM
Post: #2
PeteManchester Offline
Member
***
 		Posts: 58
Joined: Mar 2013
Reputation: 0
RE: Bad Request
I've just been looking at this one again in WireShark and it looks like it is the Control Point that is returning the BadRequest message in response to propertyset messages from the renderer.

If that's the case I'm not sure if anything can be done from the OpenHome side...



Code:
NOTIFY /event HTTP/1.1
Host: 192.168.1.72:52821
Content-Type: text/xml; charset="utf-8"
Nt: upnp:event
Nts: upnp:propchange
SID: uuid:device-Eclipse-D067E5492684-MediaRenderer-2
Transfer-Encoding: chunked Seq: 0
Connection: close
286
<?xml version="1.0"?><e:propertyset xmlns:e="urn:schemas-upnp-org:event-1-0"><e:property><Volume>100</Volume></e:property><e:property><Mute>0</Mute></e:property><e:property><Balance>0</Balance></e:property><e:property><Fade>0</Fade></e:property><e:property><VolumeLimit>100</VolumeLimit></e:property><e:property><VolumeMax>100</VolumeMax></e:property><e:property><VolumeUnity>80</VolumeUnity></e:property><e:property><VolumeSteps>100</VolumeSteps></e:property><e:property><VolumeMilliDbPerStep>1024</VolumeMilliDbPerStep></e:property><e:property><BalanceMax>0</BalanceMax></e:property><e:property><FadeMax>0</FadeMax></e:property></e:propertyset> 0

HTTP/1.1 400 Bad Request
Accept-Ranges: bytes
Content-Length: 0
Connection: close
Date: Wed, 02 Oct 2013 13:35:04 GMT
Find all posts by this user
03-10-2013, 08:26 AM
Post: #3
simonc Offline
OpenHome developer
 		Posts: 646
Joined: Jul 2011
Reputation: 8
RE: Bad Request
Thanks for tracking this down Pete. I agree that it looks like its caused by a buggy control point which doesn't support chunked requests (the final paragraph of RFC 2616 s3.6.1 states that support for chunking is mandatory).

Before I assume ohNet is blameless here, can I check a couple of things:
  • The HTTP request you show (the evented update from ohNet) isn't quite valid. There are a couple of newlines missing. I presume this is a typo; if it isn't, there's a bug in ohNet.
  • Would it be possible for you to check which HTTP version the control point used in its earlier SUBSCRIBE request? If it used 1.0, ohNet could potentially try sending an update without chunking. (This might end up violating the 1.0 spec but the worst that'd happen would be that evented updates still wouldn't work!)
Find all posts by this user
03-10-2013, 09:58 AM
Post: #4
PeteManchester Offline
Member
***
 		Posts: 58
Joined: Mar 2013
Reputation: 0
RE: Bad Request
(03-10-2013 08:26 AM)simonc Wrote:  Before I assume ohNet is blameless here, can I check a couple of things:
  • The HTTP request you show (the evented update from ohNet) isn't quite valid. There are a couple of newlines missing. I presume this is a typo; if it isn't, there's a bug in ohNet.
  • Would it be possible for you to check which HTTP version the control point used in its earlier SUBSCRIBE request? If it used 1.0, ohNet could potentially try sending an update without chunking. (This might end up violating the 1.0 spec but the worst that'd happen would be that evented updates still wouldn't work!)

Hi Simon,

The error you see with the newlines missing is my fault, I edited the text trying to make it easier to read..

Here is a subscription request:

Code:
SUBSCRIBE /device-Eclipse-D067E5492684-MediaRenderer/av.openhome.org-Product-1/event HTTP/1.1

Host: 192.168.1.72:52821

Callback: <http://192.168.1.184:50712/event>

Accept: */*

Accept-Encoding: gzip, deflate

Accept-Language: en-gb

Content-Length: 0

NT: upnp:event

Connection: keep-alive

Timeout: Second-120

User-Agent: ChorusDS UPnP/1.1 0.1



HTTP/1.1 200 OK

SERVER: Windows/6.1 UPnP/1.1 ohNet/1.0

SID: uuid:device-Eclipse-D067E5492684-MediaRenderer-2

TIMEOUT: Second-120

Connection: close
Find all posts by this user
03-10-2013, 10:01 AM
Post: #5
simonc Offline
OpenHome developer
 		Posts: 646
Joined: Jul 2011
Reputation: 8
RE: Bad Request
Thanks Pete. Looks like this is just a buggy control point.

I don't think there is anything ohNet can (should) do here. If you have the time and contact details, it might be worth informing the author of the CP about this bug however. Let me know if you need any details about ohNet's behaviour to help with this.
Find all posts by this user


Forum Jump:


Contact Us | OpenHome | Return to Top | Return to Content | Lite (Archive) Mode | RSS Syndication