New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Data clipping over 64 bytes #1229

Closed
tuna-f1sh opened this Issue Jul 13, 2017 · 24 comments

Comments

3 participants
@tuna-f1sh
Contributor

tuna-f1sh commented Jul 13, 2017

  • SerialPort Version: 5.0.0-beta7

  • NodeJS Version: 8.1.3

  • Operating System and Hardware Platform: macOS, wchusbserial USB serial

  • Have you checked the right version of the api docs?: YES

  • Are you having trouble installing and you checked the Installation Special Cases docs? NO

  • Are you using Electron and have you checked the Electron Docs?: NO

Summary of Problem

My data stream seems to be being clipped to around 64 bytes. I'm trying to send 120 bytes in total but they don't come through. This sounds like a noddy issue but it's really got me stumped!

I'm driving a Hanover Flipdot display over RS485. I have a driver in Python working successfully but wish to use Node for an app idea I have. I've used nodeserial in the past successfully but not with large buffers.

Steps and Code to Reproduce the Issue

The code I'm developing here: https://github.com/tuna-f1sh/flipdot

I can reproduce it however simply by sending a buffer larger than 64 bytes:

var SerialPort = require('serialport');
var port = new SerialPort('/dev/tty.wchusbserial1420', {
  baudRate: 4800
});

port.write(new Buffer(256), function(err) {
  if (err) {
    return console.log('Error on write: ', err.message);
  }
  console.log('message written');
});

// Open errors will be emitted as an error event
port.on('error', function(err) {
  console.log('Error: ', err.message);
});

screen shot 2017-07-13 at 13 31 48

Diagnosed by scoping the output. You'll notice the baud rate is quite slow (4800) but should take 533 ms to transmit 256 bytes. The message is ~133 ms then ends however (64 bytes). Changing the baud rate (doubling to 9600), only halves the time ~66 ms so it still clips.

Shortening the buffer to 1 byte and running the script above, the transmission will remain 64 bytes for a few runs before just transmitting 1 byte as requested - it's although the driver is unloading the previous data at write!...

I've confirmed that the highWaterMark is nothing silly and even set it to 32 kB. I've tried a lot of things so hopefully this isn't something stupid and is a bug?

@reconbot

This comment has been minimized.

Show comment
Hide comment
@reconbot

reconbot Jul 15, 2017

Member

Our tests cover lots of small writes and few large writes (up to 5k) and haven't shown any issues. I don't really understand what you mean by clips. Do you mean you're losing data and not all of the writes are being written?

Member

reconbot commented Jul 15, 2017

Our tests cover lots of small writes and few large writes (up to 5k) and haven't shown any issues. I don't really understand what you mean by clips. Do you mean you're losing data and not all of the writes are being written?

@reconbot reconbot added the support label Jul 15, 2017

@tuna-f1sh

This comment has been minimized.

Show comment
Hide comment
@tuna-f1sh

tuna-f1sh Jul 16, 2017

Contributor

Yes that is correct; not all the bytes are being written to the hardware. I know the hardware is working because I have scoped the output of the same code ported to Python. If you see in my OP, the period of transmission does not equal what it should for the number of bytes being written, nor does the device receive the full data stream.

Are the tests conducted at a hardware level too? I realise it is unlikely that this is an actual bug with node-serialport but I am at a loss as to what else could be causing this. I am not at my desk now but aim to do some more digging during the week.

Contributor

tuna-f1sh commented Jul 16, 2017

Yes that is correct; not all the bytes are being written to the hardware. I know the hardware is working because I have scoped the output of the same code ported to Python. If you see in my OP, the period of transmission does not equal what it should for the number of bytes being written, nor does the device receive the full data stream.

Are the tests conducted at a hardware level too? I realise it is unlikely that this is an actual bug with node-serialport but I am at a loss as to what else could be causing this. I am not at my desk now but aim to do some more digging during the week.

@reconbot

This comment has been minimized.

Show comment
Hide comment
@reconbot

reconbot Jul 17, 2017

Member

Yeah, the integration tests are run on osx, linux and windows in a vm with a real arduino at 9600 buad. We can do some system level tests on the ci's too. I'll leave some comments on your repo. I Think your call to flush on open might be your problem.

Member

reconbot commented Jul 17, 2017

Yeah, the integration tests are run on osx, linux and windows in a vm with a real arduino at 9600 buad. We can do some system level tests on the ci's too. I'll leave some comments on your repo. I Think your call to flush on open might be your problem.

@RogerHardiman

This comment has been minimized.

Show comment
Hide comment
@RogerHardiman

RogerHardiman Jul 17, 2017

Contributor

Just a thought, but have you tried a different USB serial port on the Mac - one with a FTDI or PL2303 chipset?

One of the USB Serial Adapters I have reports itself as a CH240 (so the wch chipset) and that never worked correctly on the Mac with node-serialport.
Everything was fine with the FTDI based USB serial port.

My wch based USB Serial Port was fine on Windows, so it pointed to an issue at the operating system driver level when the OS talks to the hardware.

Contributor

RogerHardiman commented Jul 17, 2017

Just a thought, but have you tried a different USB serial port on the Mac - one with a FTDI or PL2303 chipset?

One of the USB Serial Adapters I have reports itself as a CH240 (so the wch chipset) and that never worked correctly on the Mac with node-serialport.
Everything was fine with the FTDI based USB serial port.

My wch based USB Serial Port was fine on Windows, so it pointed to an issue at the operating system driver level when the OS talks to the hardware.

@tuna-f1sh

This comment has been minimized.

Show comment
Hide comment
@tuna-f1sh

tuna-f1sh Jul 17, 2017

Contributor

Thanks for the code comments @reconbot, I'll take them into account. Unfortunately it is not due to flush as I have isolated the problem to the example code in my OP to reproduce the problem. I've got a Saleae now so can capture better serial outputs. See the below screen shot using port.write(new Buffer(256)... as above @ 4800 baud. The full transmission should contain 256 bytes and take 533 ms but stops at 64 bytes (133 ms).

screenshot

I'll see if I can find another USB serial adaptor @RogerHardiman, I'm hoping that it is this! The adaptor works fine with pyserial but perhaps it outputs the stream to the OS driver differently...

Contributor

tuna-f1sh commented Jul 17, 2017

Thanks for the code comments @reconbot, I'll take them into account. Unfortunately it is not due to flush as I have isolated the problem to the example code in my OP to reproduce the problem. I've got a Saleae now so can capture better serial outputs. See the below screen shot using port.write(new Buffer(256)... as above @ 4800 baud. The full transmission should contain 256 bytes and take 533 ms but stops at 64 bytes (133 ms).

screenshot

I'll see if I can find another USB serial adaptor @RogerHardiman, I'm hoping that it is this! The adaptor works fine with pyserial but perhaps it outputs the stream to the OS driver differently...

@tuna-f1sh

This comment has been minimized.

Show comment
Hide comment
@tuna-f1sh

tuna-f1sh Jul 17, 2017

Contributor

Getting somewhere slightly. I've run the basic serial 256 byte buffer test with a FTDI USB serial in my Arch VM and it works fine (see full 256 byte capture below)! The same FTDI USB serial on my macOS install (10.12.5) produces even shorten results than the CH240 (only 6 bytes output)?!. Something odd is going on with the USB serial drivers on at least my macOS install, but only for node-serialport 🤔 .

So far have tried npm reinstall serialport, reboot of computer and reinstall of CH340 drivers to no avail. Good news is that the CH340 (on RS485 device) and my flipdot driver work in Arch Linux 👍.

arch-vm

Contributor

tuna-f1sh commented Jul 17, 2017

Getting somewhere slightly. I've run the basic serial 256 byte buffer test with a FTDI USB serial in my Arch VM and it works fine (see full 256 byte capture below)! The same FTDI USB serial on my macOS install (10.12.5) produces even shorten results than the CH240 (only 6 bytes output)?!. Something odd is going on with the USB serial drivers on at least my macOS install, but only for node-serialport 🤔 .

So far have tried npm reinstall serialport, reboot of computer and reinstall of CH340 drivers to no avail. Good news is that the CH340 (on RS485 device) and my flipdot driver work in Arch Linux 👍.

arch-vm

@reconbot

This comment has been minimized.

Show comment
Hide comment
@reconbot

reconbot Jul 17, 2017

Member

We shouldn't do much different than pyserial, but whatever it is we can figure it out. Before we try dumping system calls lets try one more thing. I just released 5.0.0-beta8 which has more debug output.

Can you run

DEBUG=serialport* node yourScript.js

And attach the output?

Member

reconbot commented Jul 17, 2017

We shouldn't do much different than pyserial, but whatever it is we can figure it out. Before we try dumping system calls lets try one more thing. I just released 5.0.0-beta8 which has more debug output.

Can you run

DEBUG=serialport* node yourScript.js

And attach the output?

@tuna-f1sh

This comment has been minimized.

Show comment
Hide comment
@tuna-f1sh

tuna-f1sh Jul 18, 2017

Contributor

Ok, here's the output on the Arch Linux VM:

serialport:binding:auto-detect loading LinuxBinding +0ms
serialport:main opening path: /dev/ttyUSB0 +24ms
serialport:bindings open +2ms
serialport:poller Creating poller +34ms
serialport:main opened path: /dev/ttyUSB0 +0ms
serialport:main _write 256 bytes of data +1ms
serialport:bindings write 256 bytes +1ms
serialport:unixWrite Starting write 256 bytes offset 0 bytesToWrite 256 +0ms
serialport:unixWrite write returned null 256 +1ms
serialport:unixWrite wrote 256 bytes +1ms
serialport:unixWrite Finished writing 256 bytes +0ms
serialport:main binding.write write finished +0ms

Here it is on the problematic macOS:

serialport:binding:auto-detect loading DarwinBinding +0ms
serialport:main opening path: /dev/tty.wchusbserial1420 +20ms
serialport:bindings open +2ms
serialport:poller Creating poller +1ms
serialport:main opened path: /dev/tty.wchusbserial1420 +1ms
serialport:main _write 256 bytes of data +0ms
serialport:bindings write 256 bytes +1ms
serialport:unixWrite Starting write 256 bytes offset 0 bytesToWrite 256 +0ms
serialport:unixWrite write returned null 256 +0ms
serialport:unixWrite wrote 256 bytes +0ms
serialport:unixWrite Finished writing 256 bytes +0ms
serialport:main binding.write write finished +0ms

Contributor

tuna-f1sh commented Jul 18, 2017

Ok, here's the output on the Arch Linux VM:

serialport:binding:auto-detect loading LinuxBinding +0ms
serialport:main opening path: /dev/ttyUSB0 +24ms
serialport:bindings open +2ms
serialport:poller Creating poller +34ms
serialport:main opened path: /dev/ttyUSB0 +0ms
serialport:main _write 256 bytes of data +1ms
serialport:bindings write 256 bytes +1ms
serialport:unixWrite Starting write 256 bytes offset 0 bytesToWrite 256 +0ms
serialport:unixWrite write returned null 256 +1ms
serialport:unixWrite wrote 256 bytes +1ms
serialport:unixWrite Finished writing 256 bytes +0ms
serialport:main binding.write write finished +0ms

Here it is on the problematic macOS:

serialport:binding:auto-detect loading DarwinBinding +0ms
serialport:main opening path: /dev/tty.wchusbserial1420 +20ms
serialport:bindings open +2ms
serialport:poller Creating poller +1ms
serialport:main opened path: /dev/tty.wchusbserial1420 +1ms
serialport:main _write 256 bytes of data +0ms
serialport:bindings write 256 bytes +1ms
serialport:unixWrite Starting write 256 bytes offset 0 bytesToWrite 256 +0ms
serialport:unixWrite write returned null 256 +0ms
serialport:unixWrite wrote 256 bytes +0ms
serialport:unixWrite Finished writing 256 bytes +0ms
serialport:main binding.write write finished +0ms

@tuna-f1sh

This comment has been minimized.

Show comment
Hide comment
@tuna-f1sh

tuna-f1sh Jul 18, 2017

Contributor

I've done some more digging after considering the fact that I use FTDI devices on my Nixie Pipe project and sucessfully communicate using the node module I wrote for that.

I copied the test script to that project in case the node-gyp compilation was changing. This project also uses serialport-4.0.7. The buffer unloads correctly! So the OS drivers work fine and it is working with the later versions of node-serialport on my macOS install..

The scripts act differently however. On the node-nixiepipe project, the script does not exit after sending the data. On the new project, the script exits back to the terminal after sending the data. What causes this behaviour? Is there a chance the script exiting and closing node destroys the data in the serial port driver?

I have now isolated it to the node-serialport version by rolling my flip dot project back to serialport-4.0.7. As I say above, one immediately noticeable difference is that the script does not exit at the end (one must Ctrl-C) in 4.0.7 unlike 5.0.7-> - do you know why there is this difference?

Contributor

tuna-f1sh commented Jul 18, 2017

I've done some more digging after considering the fact that I use FTDI devices on my Nixie Pipe project and sucessfully communicate using the node module I wrote for that.

I copied the test script to that project in case the node-gyp compilation was changing. This project also uses serialport-4.0.7. The buffer unloads correctly! So the OS drivers work fine and it is working with the later versions of node-serialport on my macOS install..

The scripts act differently however. On the node-nixiepipe project, the script does not exit after sending the data. On the new project, the script exits back to the terminal after sending the data. What causes this behaviour? Is there a chance the script exiting and closing node destroys the data in the serial port driver?

I have now isolated it to the node-serialport version by rolling my flip dot project back to serialport-4.0.7. As I say above, one immediately noticeable difference is that the script does not exit at the end (one must Ctrl-C) in 4.0.7 unlike 5.0.7-> - do you know why there is this difference?

@tuna-f1sh tuna-f1sh closed this Jul 18, 2017

@tuna-f1sh tuna-f1sh reopened this Jul 18, 2017

@tuna-f1sh

This comment has been minimized.

Show comment
Hide comment
@tuna-f1sh

tuna-f1sh Jul 18, 2017

Contributor

thanks for help so far!

Contributor

tuna-f1sh commented Jul 18, 2017

thanks for help so far!

@reconbot

This comment has been minimized.

Show comment
Hide comment
@reconbot

reconbot Jul 19, 2017

Member

In 5x can you call port.drain (and then console.log) after the write? You might be on to something.

The main difference is that in 4x the poller would keep node listening, and in 5x only if there is a pending read or write will node keep listening.

Member

reconbot commented Jul 19, 2017

In 5x can you call port.drain (and then console.log) after the write? You might be on to something.

The main difference is that in 4x the poller would keep node listening, and in 5x only if there is a pending read or write will node keep listening.

@reconbot

This comment has been minimized.

Show comment
Hide comment
@reconbot

reconbot Jul 19, 2017

Member

BTW that video really made my day 🤗

Member

reconbot commented Jul 19, 2017

BTW that video really made my day 🤗

@tuna-f1sh

This comment has been minimized.

Show comment
Hide comment
@tuna-f1sh

tuna-f1sh Jul 20, 2017

Contributor

Glad to hear it!

I updated the test script gist to drain, inside the write callback, and this works (the full data is output to the device on 5->. I copied it from the drain.js example. The example has the drain call outside the write callback however, but if I am not mistaken, this causes it to execute before the data has been written and so is useless due to the async nature of node (it did not work)?

Contributor

tuna-f1sh commented Jul 20, 2017

Glad to hear it!

I updated the test script gist to drain, inside the write callback, and this works (the full data is output to the device on 5->. I copied it from the drain.js example. The example has the drain call outside the write callback however, but if I am not mistaken, this causes it to execute before the data has been written and so is useless due to the async nature of node (it did not work)?

@reconbot

This comment has been minimized.

Show comment
Hide comment
@reconbot

reconbot Jul 20, 2017

Member

It is supposed to work outside the callback I have it wait for a pending write to finish internally. 🤔

In any case it works! 🎉

We figured it out, the port was being closed before the OS buffers finished draining because node was exiting. I wonder if I can add an internal call to drain when the port goes out of scope without causing trouble.

Member

reconbot commented Jul 20, 2017

It is supposed to work outside the callback I have it wait for a pending write to finish internally. 🤔

In any case it works! 🎉

We figured it out, the port was being closed before the OS buffers finished draining because node was exiting. I wonder if I can add an internal call to drain when the port goes out of scope without causing trouble.

@tuna-f1sh

This comment has been minimized.

Show comment
Hide comment
@tuna-f1sh

tuna-f1sh Jul 20, 2017

Contributor

Yes, problem solved - thanks for the help. I've fixed it in my code by adding drain in the main send function (annoyingly, I toyed with this at the very beginning but must have missed something).

I think this is a good idea if possible to change the operation. Or change the docs to include the call to drain inside the write callback if the user is running as a single run script. I think others will encounter the same problem otherwise.

In the example script, the console.log outputs 'Calling drain' and 'Drain callback returned' before 'message written' so they are executing before the pending write is even issued (perhaps creating a larger buffer takes time before the call). I can create a pull request with the working version if you would like.

Contributor

tuna-f1sh commented Jul 20, 2017

Yes, problem solved - thanks for the help. I've fixed it in my code by adding drain in the main send function (annoyingly, I toyed with this at the very beginning but must have missed something).

I think this is a good idea if possible to change the operation. Or change the docs to include the call to drain inside the write callback if the user is running as a single run script. I think others will encounter the same problem otherwise.

In the example script, the console.log outputs 'Calling drain' and 'Drain callback returned' before 'message written' so they are executing before the pending write is even issued (perhaps creating a larger buffer takes time before the call). I can create a pull request with the working version if you would like.

@reconbot

This comment has been minimized.

Show comment
Hide comment
@reconbot

reconbot Jul 20, 2017

Member

I'd love that.

When I have some time I'll look into properly fixing it so you don't have to call drain the callback. I know it works at the binding level but I guess it doesn't work in the serialport level.

Member

reconbot commented Jul 20, 2017

I'd love that.

When I have some time I'll look into properly fixing it so you don't have to call drain the callback. I know it works at the binding level but I guess it doesn't work in the serialport level.

reconbot added a commit that referenced this issue Jul 21, 2017

WIP Test drains
I can't get drain to not work right in a test. However when called sequentially write, and drain don't always work.

closes #1229

@reconbot reconbot referenced this issue Jul 21, 2017

Merged

Queue drains #1244

@reconbot reconbot added the docs label Jul 21, 2017

reconbot added a commit that referenced this issue Jul 22, 2017

Test drains
I can't get drain to fail in tests. However when called sequentially write, and drain don't always work per #1229
@reconbot

This comment has been minimized.

Show comment
Hide comment
@reconbot

reconbot Jul 23, 2017

Member

I've got some tests that say this works fine but I don't believe them. I don't know if it would be possible for me to automate a test that closes node. Maybe in a child process but.. probably not worth the effort.

I'm trying to dream up a manual test that I can do with an arduino in echo mode. Any ideas?

Can you give me the DEBUG=serialport* output for having the drain outside of the write callback with 5x. If it clips the data and what version of node?

Thanks!

Member

reconbot commented Jul 23, 2017

I've got some tests that say this works fine but I don't believe them. I don't know if it would be possible for me to automate a test that closes node. Maybe in a child process but.. probably not worth the effort.

I'm trying to dream up a manual test that I can do with an arduino in echo mode. Any ideas?

Can you give me the DEBUG=serialport* output for having the drain outside of the write callback with 5x. If it clips the data and what version of node?

Thanks!

@tuna-f1sh

This comment has been minimized.

Show comment
Hide comment
@tuna-f1sh

tuna-f1sh Jul 23, 2017

Contributor

Yep, here is the output of debug. You'll see that 'drain attemped, but port not open' shows as it happens before the write is called.

serialport:binding:auto-detect loading DarwinBinding +0ms
serialport:main opening path: /dev/tty.wchusbserial1420 +12ms
serialport:bindings open +1ms
Calling drain
serialport:main drain attempted, but port is not open +4ms
Drain callback returned
serialport:poller Creating poller +2ms
serialport:main opened path: /dev/tty.wchusbserial1420 +0ms
port opened
serialport:main _write 1024 bytes of data +1ms
serialport:bindings write 1024 bytes +0ms
serialport:unixWrite Starting write 1024 bytes offset 0 bytesToWrite 1024 +1ms
serialport:unixWrite write returned null 1024 +1ms
serialport:unixWrite wrote 1024 bytes +0ms
serialport:unixWrite Finished writing 1024 bytes +0ms
serialport:main binding.write write finished +0ms
Write callback returned

Contributor

tuna-f1sh commented Jul 23, 2017

Yep, here is the output of debug. You'll see that 'drain attemped, but port not open' shows as it happens before the write is called.

serialport:binding:auto-detect loading DarwinBinding +0ms
serialport:main opening path: /dev/tty.wchusbserial1420 +12ms
serialport:bindings open +1ms
Calling drain
serialport:main drain attempted, but port is not open +4ms
Drain callback returned
serialport:poller Creating poller +2ms
serialport:main opened path: /dev/tty.wchusbserial1420 +0ms
port opened
serialport:main _write 1024 bytes of data +1ms
serialport:bindings write 1024 bytes +0ms
serialport:unixWrite Starting write 1024 bytes offset 0 bytesToWrite 1024 +1ms
serialport:unixWrite write returned null 1024 +1ms
serialport:unixWrite wrote 1024 bytes +0ms
serialport:unixWrite Finished writing 1024 bytes +0ms
serialport:main binding.write write finished +0ms
Write callback returned

@tuna-f1sh

This comment has been minimized.

Show comment
Hide comment
@tuna-f1sh

tuna-f1sh Jul 23, 2017

Contributor

In terms of a manual test, I've created something. It does use child process as I couldn't think of a better option.

I've added it to my fork in manual-testing. It should exit status ok (0) if expected number of bytes are received, otherwise error (1). It does require two USB serial adaptors to use however, the second device must be set as an environmental variable. Example usage:

TEST_PORT=/dev/tty.wchusbserial1420 TEST_PORT_RX=/dev/tty.SLAB_USBtoUART DEBUG=* node test/manual-testing/read.js

It works quite well, and during my testing I actually found something quite enlightening. Enclosing the code in the 'open' callback, the device successfully drains before closing.

WORKS

const serialPort = new SerialPort(port, (err) => {
  if (err) { throw err }

  const largeMessage = Buffer.alloc(512, '!');
  console.log(`Writting data dength: ${largeMessage.length} B`);
  serialPort.write(largeMessage, () => {
    console.log('Write callback returned');
  });

  // At this point, data may still be buffered in the os or node serialserialPort and not sent
  // out over the serialPort yet. SerialserialPort will wait until any pending writes have completed and then ask
  // the operating system to wait until all data has been written to the file descriptor.
  console.log('Calling drain');
  serialPort.drain(() => {
    console.log('Drain callback returned');
    // Now the data has "left the pipe" (tcdrain[1]/FlushFileBuffers[2] finished blocking).
    // [1] http://linux.die.net/man/3/tcdrain
    // [2] http://msdn.microsoft.com/en-us/library/windows/desktop/aa364439(v=vs.85).aserialPortx
  });
});

serialport:binding:auto-detect loading DarwinBinding +0ms
serialport:main opening path: /dev/tty.SLAB_USBtoUART +15ms
serialport:bindings open +1ms
serialport:poller Creating poller +9ms
serialport:main opened path: /dev/tty.SLAB_USBtoUART +1ms
Writting data dength: 512 B
Calling drain
Drain callback returned
Write callback returned

serialport:main _read discarding the read buffer pool +214ms
serialport:main _read reading +0ms
serialport:bindings read +1ms
serialport:unixRead Starting read +2ms
serialport:unixRead Finished read 64 bytes +0ms
serialport:main binding.read finished +1ms
Recieved data dength: 64 B

DOES DRAIN FULLY

const serialPort = new SerialPort(port, (err) => {
  if (err) { throw err }
});

const largeMessage = Buffer.alloc(512, '!');
console.log(`Writting data dength: ${largeMessage.length} B`);
serialPort.write(largeMessage, () => {
  console.log('Write callback returned');
});

// At this point, data may still be buffered in the os or node serialserialPort and not sent
// out over the serialPort yet. SerialserialPort will wait until any pending writes have completed and then ask
// the operating system to wait until all data has been written to the file descriptor.
console.log('Calling drain');
serialPort.drain(() => {
  console.log('Drain callback returned');
  // Now the data has "left the pipe" (tcdrain[1]/FlushFileBuffers[2] finished blocking).
  // [1] http://linux.die.net/man/3/tcdrain
  // [2] http://msdn.microsoft.com/en-us/library/windows/desktop/aa364439(v=vs.85).aserialPortx
});

serialport:binding:auto-detect loading DarwinBinding +0ms
serialport:main opening path: /dev/tty.SLAB_USBtoUART +17ms
serialport:bindings open +0ms
serialport:poller Creating poller +10ms
serialport:main opened path: /dev/tty.SLAB_USBtoUART +0ms
Writting data dength: 512 B
Calling drain
Write callback returned
Drain callback returned

serialport:main _read discarding the read buffer pool +2s
serialport:main _read reading +0ms
serialport:bindings read +0ms
serialport:unixRead Starting read +1ms
serialport:unixRead Finished read 512 bytes +2ms
serialport:main binding.read finished +0ms
Recieved data dength: 512 B

Contributor

tuna-f1sh commented Jul 23, 2017

In terms of a manual test, I've created something. It does use child process as I couldn't think of a better option.

I've added it to my fork in manual-testing. It should exit status ok (0) if expected number of bytes are received, otherwise error (1). It does require two USB serial adaptors to use however, the second device must be set as an environmental variable. Example usage:

TEST_PORT=/dev/tty.wchusbserial1420 TEST_PORT_RX=/dev/tty.SLAB_USBtoUART DEBUG=* node test/manual-testing/read.js

It works quite well, and during my testing I actually found something quite enlightening. Enclosing the code in the 'open' callback, the device successfully drains before closing.

WORKS

const serialPort = new SerialPort(port, (err) => {
  if (err) { throw err }

  const largeMessage = Buffer.alloc(512, '!');
  console.log(`Writting data dength: ${largeMessage.length} B`);
  serialPort.write(largeMessage, () => {
    console.log('Write callback returned');
  });

  // At this point, data may still be buffered in the os or node serialserialPort and not sent
  // out over the serialPort yet. SerialserialPort will wait until any pending writes have completed and then ask
  // the operating system to wait until all data has been written to the file descriptor.
  console.log('Calling drain');
  serialPort.drain(() => {
    console.log('Drain callback returned');
    // Now the data has "left the pipe" (tcdrain[1]/FlushFileBuffers[2] finished blocking).
    // [1] http://linux.die.net/man/3/tcdrain
    // [2] http://msdn.microsoft.com/en-us/library/windows/desktop/aa364439(v=vs.85).aserialPortx
  });
});

serialport:binding:auto-detect loading DarwinBinding +0ms
serialport:main opening path: /dev/tty.SLAB_USBtoUART +15ms
serialport:bindings open +1ms
serialport:poller Creating poller +9ms
serialport:main opened path: /dev/tty.SLAB_USBtoUART +1ms
Writting data dength: 512 B
Calling drain
Drain callback returned
Write callback returned

serialport:main _read discarding the read buffer pool +214ms
serialport:main _read reading +0ms
serialport:bindings read +1ms
serialport:unixRead Starting read +2ms
serialport:unixRead Finished read 64 bytes +0ms
serialport:main binding.read finished +1ms
Recieved data dength: 64 B

DOES DRAIN FULLY

const serialPort = new SerialPort(port, (err) => {
  if (err) { throw err }
});

const largeMessage = Buffer.alloc(512, '!');
console.log(`Writting data dength: ${largeMessage.length} B`);
serialPort.write(largeMessage, () => {
  console.log('Write callback returned');
});

// At this point, data may still be buffered in the os or node serialserialPort and not sent
// out over the serialPort yet. SerialserialPort will wait until any pending writes have completed and then ask
// the operating system to wait until all data has been written to the file descriptor.
console.log('Calling drain');
serialPort.drain(() => {
  console.log('Drain callback returned');
  // Now the data has "left the pipe" (tcdrain[1]/FlushFileBuffers[2] finished blocking).
  // [1] http://linux.die.net/man/3/tcdrain
  // [2] http://msdn.microsoft.com/en-us/library/windows/desktop/aa364439(v=vs.85).aserialPortx
});

serialport:binding:auto-detect loading DarwinBinding +0ms
serialport:main opening path: /dev/tty.SLAB_USBtoUART +17ms
serialport:bindings open +0ms
serialport:poller Creating poller +10ms
serialport:main opened path: /dev/tty.SLAB_USBtoUART +0ms
Writting data dength: 512 B
Calling drain
Write callback returned
Drain callback returned

serialport:main _read discarding the read buffer pool +2s
serialport:main _read reading +0ms
serialport:bindings read +0ms
serialport:unixRead Starting read +1ms
serialport:unixRead Finished read 512 bytes +2ms
serialport:main binding.read finished +0ms
Recieved data dength: 512 B

tuna-f1sh referenced this issue in tuna-f1sh/node-serialport Jul 23, 2017

@reconbot

This comment has been minimized.

Show comment
Hide comment
@reconbot

reconbot Jul 23, 2017

Member
Member

reconbot commented Jul 23, 2017

@reconbot

This comment has been minimized.

Show comment
Hide comment
@reconbot

reconbot Jul 23, 2017

Member

In any case I think it's worth landing the manual test. Good to have a multi adaptor example to reference.

Member

reconbot commented Jul 23, 2017

In any case I think it's worth landing the manual test. Good to have a multi adaptor example to reference.

reconbot added a commit that referenced this issue Jul 24, 2017

Queue drains
Drains don't make any sense if called on a closed port or before any writes. I'm queuing drains so they run one the port opens, just like `write()` this allows for a much easier time ensuring all data is written in a script.

- `drain()` waits for an open event if the port is closed
-  mock-bindings now cancel pending reads

closes #1229

reconbot added a commit that referenced this issue Jul 24, 2017

Queue drains
Drains don't make any sense if called on a closed port or before any writes. I'm queuing drains so they run one the port opens, just like `write()` this allows for a much easier time ensuring all data is written in a script.

- `drain()` waits for an open event if the port is closed
-  mock-bindings now cancel pending reads

closes #1229
@reconbot

This comment has been minimized.

Show comment
Hide comment
@reconbot

reconbot Jul 24, 2017

Member

I got the drain tests working, the drains queued behind port opening, and it's looking good to me. I think it will be a lot easier to use now.

Thanks for all your work on this. And thanks for writing a multi adaptor test! That will be really helpful in the future.

#1244

Member

reconbot commented Jul 24, 2017

I got the drain tests working, the drains queued behind port opening, and it's looking good to me. I think it will be a lot easier to use now.

Thanks for all your work on this. And thanks for writing a multi adaptor test! That will be really helpful in the future.

#1244

@tuna-f1sh

This comment has been minimized.

Show comment
Hide comment
@tuna-f1sh

tuna-f1sh Jul 24, 2017

Contributor

Cool, glad to have helped such a useful module. I think it makes sense to queue the drain like everything else. Shall I create a pull request to add the manual test?

Contributor

tuna-f1sh commented Jul 24, 2017

Cool, glad to have helped such a useful module. I think it makes sense to queue the drain like everything else. Shall I create a pull request to add the manual test?

@reconbot

This comment has been minimized.

Show comment
Hide comment
@reconbot

reconbot Jul 24, 2017

Member
Member

reconbot commented Jul 24, 2017

reconbot added a commit that referenced this issue Jul 24, 2017

Queue drains
Drains don't make any sense if called on a closed port or before any writes. I'm queuing drains so they run one the port opens, just like `write()` this allows for a much easier time ensuring all data is written in a script.

- `drain()` waits for an open event if the port is closed
-  mock-bindings now cancel pending reads

closes #1229

reconbot added a commit that referenced this issue Jul 25, 2017

Queue drains
Drains don't make any sense if called on a closed port or before any writes. I'm queuing drains so they run one the port opens, just like `write()` this allows for a much easier time ensuring all data is written in a script.

- `drain()` waits for an open event if the port is closed
-  mock-bindings now cancel pending reads

closes #1229

@reconbot reconbot added the bug label Jul 25, 2017

@lock lock bot locked and limited conversation to collaborators Feb 5, 2018

reconbot added a commit that referenced this issue Jul 24, 2018

Queue drains
Drains don't make any sense if called on a closed port or before any writes. I'm queuing drains so they run one the port opens, just like `write()` this allows for a much easier time ensuring all data is written in a script.

- `drain()` waits for an open event if the port is closed
-  mock-bindings now cancel pending reads

closes #1229
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.