Data getting combined incorrectly?

[djMax]

I'm using your wonderful library on OS X. I have a device which likes to send data in 256-byte or less chunks. I added an NSLog to the rfcommChannelData selector in the native side and I see these events:

2014-11-26 23:56:59.954 node[40679:338053] Received 258 from device
2014-11-26 23:57:00.013 node[40679:338053] Received 258 from device
2014-11-26 23:57:00.014 node[40679:338053] Received 156 from device

But in my data handler in node I see:
[2014-11-27 04:57:00.014 UTC] - verbose: [40679:lib/stuff.js] Received 258 bytes
[2014-11-27 04:57:00.014 UTC] - verbose: [40679:lib/stuff.js] Received 414 bytes

And the last 156 bytes of packet #2 appear to be garbage. Ideas? Could be me somehow, but not entirely sure how.

[eelcocramer]

Packet 2 in your data handler probably the first 258 bytes from packet 2 you received from your device together with 156 bytes of packet 3 that was received from your device (258+156=414). You might want to check what and why the device is sending the last 156 bytes?

[djMax]

That is what it SHOULD be and I have verified (by printing the nsdata) that it arrives in the native code in tact. But I think what's happening is it fails to combine the two buffers properly (perhaps in the pipe code)

[eelcocramer]

So the content of the buffer within the native code is not the same as what you get in the script? Can you give more details about the content. Is it total garbage or are some details missing?

Just for the record: the native code just reads raw data from the Bluetooth connection and pushes it upstream. Any parsing and validating, like splitting input based upon newlines or verify that you have a valid json or xml input, should be done by your own script. It is very likely that packets you receive in your script contain just a fragment or have some data of the next packet that was received on the Bluetooth connection.

[djMax]

Here's what shows up in the native code:

2014-11-27 08:43:33.475 node[41736:364339] Received 258 from device
<0101fee1 82028eed 15df0d0b 41525143 444f4c2e 434647df 7f04312e 3135ed14 df0d0a41 4143444f 4c2e4346 47df7f04 312e3134 ed10df0d 07656d76 2e636667 df7f0334 2e32ed18 df0d0f63 6f6e7461 63746c65 73732e63 6667df7f 03302e38 ed1adf0d 0b503250 45444f4c 2e434647 df7f094d 69757261 2d312d31 ed20df0d 10656d76 2d66616c 6c626163 6b2e6366 67df7f0a 4d697572 612d5631 2d30ed19 df0d094f 50444f4c 2e434647 df7f0a4d 69757261 2d56312d 30ed13df 0d095443 444f4c2e 434647df 7f04312e 3134ed12 df0d0854 444f4c2e 434647df 7f04312e 3132ed1b df0d0a54 524d444f 4c2e4346 47df7f0b 4d697572 612d5631 2d3031ed 1ba7>
2014-11-27 08:43:33.569 node[41736:364339] Received 258 from device
<0101fedf 0d0b6361 706b6579 732e6366 67df7f0a 54455354 2d56312d 3336ed26 df0d0f63 746c7363 61706b65 79732e63 6667df7f 1143544c 53544553 54434150 4b2d5631 2d30ed12 df0d0931 32783332 2e626466 df7f0331 2e31ed14 df0d0b6c 63642d73 74642e62 6466df7f 03312e35 ed1adf0d 0b70726f 6d707473 2e747874 df7f094d 69757261 2d312d31 ed12df0d 09313678 33302e62 6466df7f 03312e30 ed21df0d 11656d76 2d70696e 62797061 73732e63 6667df7f 0a4d6975 72612d56 302d36ed 1edf0d14 6163632d 64617461 2d70726f 6d707473 2e747874 df7f0431 2e3030ed 11df0d08 39783137 2e626466 df7f0331 2e30ed15 df0d0c73 7265642d 6de9>
2014-11-27 08:43:33.569 node[41736:364339] Received 156 from device
<01009861 672e6366 67df7f03 302e31ed 1bdf0d0b 656d762d 6172632e 636667df 7f0a4d69 7572612d 56312d33 ed11df0d 08387831 362e6264 66df7f03 312e30ed 19df0d10 63746c73 2d70726f 6d707473 2e747874 df7f0330 2e34ed20 df0d0f4d 50492d44 796e616d 69632e63 6667df7f 0b4d6975 72612d56 2d312d30 ed1bdf0d 124d5049 2d50726f 64756374 696f6e2e 636667df 7f03342e 30900061>

And here's what the node gets:

[2014-11-27 13:43:33.569 UTC] - verbose: [41736:lib/stuff.js] Received 258 bytes
0101fee182028eed15df0d0b41525143444f4c2e434647df7f04312e3135ed14df0d0a414143444f4c2e434647df7f04312e3134ed10df0d07656d762e636667df7f03342e32ed18df0d0f636f6e746163746c6573732e636667df7f03302e38ed1adf0d0b50325045444f4c2e434647df7f094d697572612d312d31ed20df0d10656d762d66616c6c6261636b2e636667df7f0a4d697572612d56312d30ed19df0d094f50444f4c2e434647df7f0a4d697572612d56312d30ed13df0d095443444f4c2e434647df7f04312e3134ed12df0d0854444f4c2e434647df7f04312e3132ed1bdf0d0a54524d444f4c2e434647df7f0b4d697572612d56312d3031ed1ba7
e182028eed15df0d0b41525143444f4c2e434647df7f04312e3135ed14df0d0a414143444f4c2e434647df7f04312e3134ed10df0d07656d762e636667df7f03342e32ed18df0d0f636f6e746163746c6573732e636667df7f03302e38ed1adf0d0b50325045444f4c2e434647df7f094d697572612d312d31ed20df0d10656d762d66616c6c6261636b2e636667df7f0a4d697572612d56312d30ed19df0d094f50444f4c2e434647df7f0a4d697572612d56312d30ed13df0d095443444f4c2e434647df7f04312e3134ed12df0d0854444f4c2e434647df7f04312e3132ed1bdf0d0a54524d444f4c2e434647df7f0b4d697572612d56312d3031ed1b
0101fedf0d0b6361706b6579732e636667df7f0a544553542d56312d3336ed26df0d0f63746c736361706b6579732e636667df7f1143544c53544553544341504b2d56312d30ed12df0d0931327833322e626466df7f03312e31ed14df0d0b6c63642d7374642e626466df7f03312e35ed1adf0d0b70726f6d7074732e747874df7f094d697572612d312d31ed12df0d0931367833302e626466df7f03312e30ed21df0d11656d762d70696e6279706173732e636667df7f0a4d697572612d56302d36ed1edf0d146163632d646174612d70726f6d7074732e747874df7f04312e3030ed11df0d08397831372e626466df7f03312e30ed15df0d0c737265642d6de90000000000000000000000000000000000000000000000000000000000000e00206465766963650a0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000a00000000000000000000000000000000000000000000000000000000000000080000000000000000000000000000000000000000000000f3030d100000

Hopefully I copied that all right but the last bit is definitely the issue - that trailing 156 is junk.

[eelcocramer]

The question is if the junk was send by the device or data the data was corrupted by this module! :-)

Any idea or means to check what is supposed to be in that last 156 bytes?

[djMax]

Yes, if I alter the sequence of outbound messages it arrives in tact. And it mirrors what shows up on the native side. But not on the node side

Sent from my iPhone 6 so I can't reach all the keys

On Nov 27, 2014, at 10:59 AM, Eelco notifications@github.com wrote:

The question is if the junk was send by the device or data the data was corrupted by this module! :-)

Any idea or means to check what is supposed to be in that last 156 bytes?

—
Reply to this email directly or view it on GitHub.

[eelcocramer]

Can you try adding a log statement after line 154 of BTSerialPortBinding.mm to check if the pipe is not corrupting the data? In that line the data is popped from the pipe as soon as it comes available.

What I find strange is that the 2 packets are pushed into the pipe before it pops the data where I would have expected the pop function to return as soon as the data of the first packet was pushed in.

[djMax]

Here's a full run log. You can see the first packet that goes out goes fine (the short response is received fine) then the second one that is returing 600+ bytes in 3 packets gets borked.

The line you asked me to add is this:
NSLog(@"154::Popped size=%ld buf size=%ld\n", size, sizeof(buf));

https://gist.github.com/djMax/82d5009accdc2c91992d

[djMax]

Will do. But couldn't that happen if my event handler hasn't processed the data fast enough?

[eelcocramer]

Thanks you for adding the log. Its pretty hard for me to understand what is happening there as I have no context.

Do you have the idea that the pipe is not popping the exact same data that is pushed?

If it's possible you might want to try running your code on Windows or Linux. These are totally independent implementations and should work fine if the problem is in the pipe code.

I did check if there is a more recent version of the pipe but I'm using the most current version of that code.

[djMax]

Understandable. I'll try it on windows and see. My guess is that somebody who's copying the buffer has bad indexes. So who does that? Just pipe?

[eelcocramer]

It is only pipe that does it. I added it just for the purpose of queuing the incoming data between threads. Its 3rd party code I got from here: https://github.com/wowus/pipe

[djMax]

I've updated the gist to be a lot more concise. You can see the rfComm input and the EIO "output" and that they don't match. I'll keep digging, but pointers where to log stuff appreciated.

https://gist.github.com/djMax/82d5009accdc2c91992d

[djMax]

Now updated with a log in the pipe_push - it's still ok by then.

[djMax]

I think the problem is here: pipe_t *pipe = pipe_new(sizeof(int), 0);

We're not passing ints (at least in this case), we're passing bytes. Doesn't matter in the single-packet case because we just overcopy (could cause a seg fault though in some cases).