03-17-2009 11:45 PM
Solved! Go to Solution.
03-18-2009 05:53 AM
I'm not familiar with the MIDLET environment, and have only posted text data, but two quick questions that might help:
1) Have set the Content Length, for example:
<connection>.setRequestProperty("Content-Length", Integer.toString(postBytesLength));
2) Does it work with Text data?
03-20-2009 02:13 PM
<2009-03-20 10:39:30.874 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1613920299, HTTPTRANSMISSION = [Transmission Line Section]:>
<2009-03-20 10:39:30.874 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1613920299, HTTPTRANSMISSION = POST /om/httpreqdecode HTTP/1.1>
<2009-03-20 10:39:30.874 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1613920299, HTTPTRANSMISSION = [Headers Section]: 3 headers>
<2009-03-20 10:39:30.874 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1613920299, HTTPTRANSMISSION = Host:localhost:8090>
<2009-03-20 10:39:30.874 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1613920299, HTTPTRANSMISSION = Content-Length:208>
<2009-03-20 10:39:30.874 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1613920299, HTTPTRANSMISSION = User-Agent:BlackBerry7290>
<2009-03-20 10:39:30.874 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1613920299, HTTPTRANSMISSION = [Parameters Section]: 0 parameters>
<2009-03-20 10:39:30.874 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1613920299, HTTPTRANSMISSION = [Entity Content Section]: 208 bytes>
<2009-03-20 10:40:14.499 PDT>:[130]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1613920300, HTTPTRANSMISSION = [Transmission Line Section]:>
<2009-03-20 10:40:14.499 PDT>:[130]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1613920300, HTTPTRANSMISSION = POST /om/devsync HTTP/1.1>
<2009-03-20 10:40:14.499 PDT>:[130]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1613920300, HTTPTRANSMISSION = [Headers Section]: 2 headers>
<2009-03-20 10:40:14.499 PDT>:[130]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1613920300, HTTPTRANSMISSION = Host:localhost:8090>
<2009-03-20 10:40:14.499 PDT>:[130]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1613920300, HTTPTRANSMISSION = User-Agent:BlackBerry7290>
<2009-03-20 10:40:14.499 PDT>:[130]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1613920300, HTTPTRANSMISSION = [Parameters Section]: 0 parameters>
<2009-03-20 10:40:14.499 PDT>:[130]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1613920300, HTTPTRANSMISSION = [Entity Content Section]: 0 bytes>
The Content-Length header in the test program log is manufactured by the simulator -- my code does not explicitly create it. Note that it does not appear in the log for the real program.
03-20-2009 04:42 PM
03-26-2009 01:45 PM
The obvious question here is what is different between your test application and real application? I also recommend enabling verbose logging in the MDS Simulator to try and get a better idea on what is being sent.
How To - Enable HTTP and HTML logging in the BlackBerry MDS Simulator
Article Number: DB-00156
03-26-2009 05:52 PM
<2009-03-26 13:30:59.296 PDT>:[101]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HTTP Thread: JobRunner-0 started>
<2009-03-26 13:30:59.296 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1720667107, HTTPTRANSMISSION = [Transmission Line Section]:>
<2009-03-26 13:30:59.296 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1720667107, HTTPTRANSMISSION = POST /om/devsync HTTP/1.1>
<2009-03-26 13:30:59.296 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1720667107, HTTPTRANSMISSION = [Headers Section]: 3 headers>
<2009-03-26 13:30:59.296 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1720667107, HTTPTRANSMISSION = Host:diamond:8090>
<2009-03-26 13:30:59.296 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1720667107, HTTPTRANSMISSION = Content-Length:208>
<2009-03-26 13:30:59.296 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1720667107, HTTPTRANSMISSION = User-Agent:BlackBerry7290>
<2009-03-26 13:30:59.296 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1720667107, HTTPTRANSMISSION = [Parameters Section]: 0 parameters>
<2009-03-26 13:30:59.296 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1720667107, HTTPTRANSMISSION = [Entity Content Section]: 208 bytes>
<2009-03-26 13:56:23.250 PDT>:[101]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HTTP Thread: JobRunner-0 started>
<2009-03-26 13:56:23.265 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 499107543, HTTPTRANSMISSION = [Transmission Line Section]:>
<2009-03-26 13:56:23.265 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 499107543, HTTPTRANSMISSION = POST /om/devsync HTTP/1.1>
<2009-03-26 13:56:23.265 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 499107543, HTTPTRANSMISSION = [Headers Section]: 2 headers>
<2009-03-26 13:56:23.265 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 499107543, HTTPTRANSMISSION = Host:diamond:8090>
<2009-03-26 13:56:23.265 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 499107543, HTTPTRANSMISSION = User-Agent:BlackBerry7290>
<2009-03-26 13:56:23.265 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 499107543, HTTPTRANSMISSION = [Parameters Section]: 0 parameters>
<2009-03-26 13:56:23.265 PDT>:[102]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = ReceivedFromDevice, DEVICEPIN = 2100000a, CONNECTIONID = 499107543, HTTPTRANSMISSION = [Entity Content Section]: 0 bytes>
I'm not seeing any significant difference between the two except for that fact that in one case the POST bytes are seen and in the other not. The Content-Length header is not generated by my code, so apparently it's generated by the device simulator.
03-26-2009 06:11 PM
[Small addendum to last post.]
On the HTTP POST OutputStream.flush issue, I do have a separate thread that updates a progress gauge and does no UI itself. I do find it odd that in the simulator, when the test case POST does get through, I don't get the confirmation question about whether I want to grant the application access to the given URL.
03-26-2009 08:57 PM
A little more data about the simulator hanging on the OutputStream.flush call of the test code that can in fact write the POST data:
In the debug pane of the JDE, when the device simulator hits the flush call:
Exit net_rim_sdk_simulationSB(66)
It seems to happen consistently there when it hangs and close to the beginning of the program on a successful run. Why would that be?
The MDS log in this case shows that the server returned the expected (110 in this case) bytes, but with the device simulator hanging on the flush call, the device simulator eventually times out:
<2009-03-26 17:36:41.218 PDT>:[390]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, EVENT = QueueSize, DEVICEPIN = 2100000a, SendingQueue = 0>
<2009-03-26 17:36:41.218 PDT>:[391]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = SentToDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1853341086, HTTPTRANSMISSION = [Transmission Line Section]:>
<2009-03-26 17:36:41.218 PDT>:[391]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = SentToDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1853341086, HTTPTRANSMISSION = HTTP/1.1 200 OK>
<2009-03-26 17:36:41.218 PDT>:[391]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = SentToDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1853341086, HTTPTRANSMISSION = [Headers Section]: 5 headers>
<2009-03-26 17:36:41.218 PDT>:[391]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = SentToDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1853341086, HTTPTRANSMISSION = Content-Type:application/x-orgmob-devsync>
<2009-03-26 17:36:41.218 PDT>:[391]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = SentToDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1853341086, HTTPTRANSMISSION = Connection:close>
<2009-03-26 17:36:41.218 PDT>:[391]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = SentToDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1853341086, HTTPTRANSMISSION = Date:Fri, 27 Mar 2009 00:36:41 GMT>
<2009-03-26 17:36:41.218 PDT>:[391]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = SentToDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1853341086, HTTPTRANSMISSION = Server:Sun Java System Application Server 9.1_02>
<2009-03-26 17:36:41.218 PDT>:[391]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = SentToDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1853341086, HTTPTRANSMISSION = X-Powered-By:Servlet/2.5>
<2009-03-26 17:36:41.218 PDT>:[391]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = SentToDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1853341086, HTTPTRANSMISSION = [Parameters Section]: 0 parameters>
<2009-03-26 17:36:41.218 PDT>:[391]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HANDLER = HTTP, EVENT = SentToDevice, DEVICEPIN = 2100000a, CONNECTIONID = 1853341086, HTTPTRANSMISSION = [Entity Content Section]: 110 bytes>
<2009-03-26 17:36:41.234 PDT>:[394]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HTTP Thread: JobRunner-7 stopping>
<2009-03-26 17:36:41.234 PDT>:[395]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HTTP Thread: JobRunner-7 stopped>
<2009-03-26 17:36:41.234 PDT>:[396]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, EVENT = Sending, TAG = 348717066, DEVICEPIN = 2100000a, VERSION = 16, CONNECTIONID = 1853341086, SEQUENCE = 0, TYPE = DATA, SIZE = 225>
<2009-03-26 17:36:41.234 PDT>:[397]:<MDS_MDS>:<DEBUG>:<LAYER = SCM, EVENT = Finished JobRunner: JobRunner-7, available threads in JobPool = 10>
<2009-03-26 17:36:41.265 PDT>:[400]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, EVENT = Sending, TAG = 348717067, DEVICEPIN = 2100000a, VERSION = 16, CONNECTIONID = 1853341086, SEQUENCE = 1, TYPE = DISCONNECT-ORDER, SIZE = 0>
<2009-03-26 17:36:41.265 PDT>:[401]:<MDS_MDS>:<DEBUG>:<LAYER = SCM, EVENT = Device connections: AVG latency (msecs)47>
<2009-03-26 17:36:41.296 PDT>:[402]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HTTP Thread: ConnectionsInputStreamesReader0-JobRunner-7 stopping>
<2009-03-26 17:36:41.296 PDT>:[403]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, HTTP Thread: ConnectionsInputStreamesReader0-JobRunner-7 stopped>
<2009-03-26 17:36:41.296 PDT>:[404]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, EVENT = RemovedReceivingQueue, DEVICEPIN:CONNECTIONID = 2100000a:1853341086, QueueSize = 0>
<2009-03-26 17:38:40.312 PDT>:[405]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, EVENT = Receiving, TAG = -1423920386, DEVICEPIN = 2100000a, VERSION = 16, CONNECTIONID = 1853341086, SEQUENCE = 1, TYPE = DISCONNECT-ORDER, SIZE = 0>
<2009-03-26 17:38:40.421 PDT>:[406]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, EVENT = RemovedSendingQueue, DEVICEPIN = 2100000a, CONNECTIONID = 1853341086, QueueSize = 1>
<2009-03-26 17:38:40.421 PDT>:[407]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, EVENT = RemovedReceivingQueue, DEVICEPIN:CONNECTIONID = 2100000a:1853341086, QueueSize = 0>
<2009-03-26 17:38:40.453 PDT>:[408]:<MDS_MDS>:<DEBUG>:<LAYER = IPPP, ERRORMSG = Invalid, DEVICEPIN:CONNECTIONID = 2100000a:1853341086, SEQUENCE = 1, Information = Received Packet for a timed out connection>
<2009-03-26 17:38:40.984 PDT>:[409]:<MDS_MDS>:<DEBUG>:<LAYER = MDP, Receiving ACK for not existing datagram>
Note: this is still the flush timeout issue in the test code; I'm still narrowing down the differences between the test and real code to try and see what the trigger for the POST stream being discarded is in the real program.
03-27-2009 08:03 PM
I've found what triggers this behavior in the simulators. I had a bug in my code which caused it to unintentionally (although permitted by RFC 2616) write an HTTP header with an empty string for a value. I would say that this then triggered a bug in the the device simulator which then swallowed that header (which explains why the header was not shown in the MDS log) and did not pass on the output stream with the HTTP POST data.
An abstraction of the code triggering the bug looks like:
// ...
String locale = functionThatReturnsEmptyString();
// ...
HttpConnection hc = (HttpConnection)Connector.open(
"http://foo.com/bar", Connector.READ_WRITE, true );
hc.setRequestMethod( HttpConnection.POST );
hc.setRequestProperty( "User-Agent", "BlackBerry7290" );
// Content-Language header value is empty string!
// and apparently never makes it from device simulator to
// MDS simulator
hc.setRequestProperty( "Content-Language", locale );
// ...
byte[] ba = dataToPostViaHttp(); // my binary POST data
DataOutputStream dos = hc.openDataOutputStream();
dos.write( ba, 0, ba.length );
// data not truly flushed due to HTTP header with empty string for value
dos.flush();
int rc = hc.getResponseCode();
DataInputStream dis = hc.openDataInputStream();
// ...
RFC 2616 at http://www.ietf.org/rfc/rfc2616.txt is pretty clear that an empty value for an HTTP header is legal in HTTP:
2 Notational Conventions and Generic Grammar
2.1 Augmented BNF
All of the mechanisms specified in this document are described in
both prose and an augmented Backus-Naur Form (BNF) similar to that
used by RFC 822 [9]. Implementors will need to be familiar with the
notation in order to understand this specification. The augmented BNF
includes the following constructs:
...
*rule
The character "*" preceding an element indicates repetition. The
full form is "<n>*<m>element" indicating at least <n> and at most
<m> occurrences of element. Default values are 0 and infinity so
that "*(element)" allows any number, including zero; "1*element"
requires at least one; and "1*2element" allows one or two.
[rule]
Square brackets enclose optional elements; "[foo bar]" is
equivalent to "*1(foo bar)".
...
4 HTTP Message
4.1 Message Types
HTTP messages consist of requests from client to server and responses
from server to client.
HTTP-message = Request | Response ; HTTP/1.1 messages
...
generic-message = start-line
*(message-header CRLF)
CRLF
[ message-body ]
start-line = Request-Line | Status-Line
...
4.2 Message Headers
HTTP header fields, which include general-header (section 4.5),
request-header (section 5.3), response-header (section 6.2), and
entity-header (section 7.1) fields, follow the same generic format as
that given in Section 3.1 of RFC 822 [9]. Each header field consists
of a name followed by a colon (":") and the field value. ...
message-header = field-name ":" [ field-value ]
field-name = token
field-value = *( field-content | LWS )
field-content = <the OCTETs making up the field-value
and consisting of either *TEXT or combinations
of token, separators, and quoted-string>
04-14-2009 03:04 PM