Access violation after 2 or 3 successive writes

[Zensey]

SerialPort version: 4.0.5
NodeJS Version: 4.5.1
Operating System and Hardware Platform: Windows XP /7/8/10

Summary of Problem:

After migration to serialport@>=4 my program started:

• to crash on Windows
• to hang on Linux

Crash condition:

2 or 3 successive writes

Test:

const
    co = require('co'),
    log4js = require('log4js'),
    SerialPort = require('serialport');
var logger = log4js.getLogger('test')

function* test_v4 () {
    var sp = new SerialPort('COM1', {baudRate: 9600, autoOpen: false})
    yield cb => sp.open(cb)
    for (var i = 1; i <= 5; i++) {
        yield cb => sp.write(new Buffer([1, 2]), cb)
        logger.info('>', i)
    }
}
co(test_v4).then(function (res) {
    logger.info('res >', res);
    process.exit()
}, function (err) {
    logger.error(err.stack);
});

Output:

C:\Shared\test>node test
[2016-11-09 23:45:54.285] [INFO] test - > 1
[2016-11-09 23:45:54.301] [INFO] test - > 2

C:\Shared\test>

As you can see for-loop does not complete.
On serialport@3 it did.

NtTrace:

...
�[32m[2016-11-09 23:17:56.637] [INFO] test - �[39m> 2
NtWriteFile( FileHandle=0x60, Event=0, ApcRoutine=null, ApcContext=null, IoStatusBlock=0xf4f178 [0/0x36], Buffer=0x25a180, Length=0x36, ByteOffset=null, Key=null ) => 0
NtReleaseKeyedEvent( KeyedEventHandle=0, Key=0x405f870, Alertable=false, Timeout=null ) => 0
NtWaitForKeyedEvent( KeyedEventHandle=0, Key=0x405f870, Alertable=false, Timeout=null ) => 0
NtSetEvent( EventHandle=0x200, PrevState=null ) => 0
NtWaitForSingleObject( Handle=0x200, Alertable=false, Timeout=null ) => 0
NtCreateEvent( EventHandle=0x405f85c [0x210], DesiredAccess=DELETE|READ_CONTROL|WRITE_DAC|WRITE_OWNER|SYNCHRONIZE|0x3, ObjectAttributes=null, EventType=0 [NotificationEvent], InitialState=false ) => 0
NtWriteFile( FileHandle=0x208, Event=0x210, ApcRoutine=null, ApcContext=0x405f8b0, IoStatusBlock=0x405f8b0, Buffer=0x25a1b8, Length=2, ByteOffset=0x405f840 [0], Key=null ) => 0x103 [997 'Протекает наложенное событие ввода/вывода.']
NtReleaseKeyedEvent( KeyedEventHandle=0, Key=0x41af700, Alertable=false, Timeout=null ) => 0
NtWaitForKeyedEvent( KeyedEventHandle=0, Key=0x41af700, Alertable=false, Timeout=null ) => 0
NtWaitForSingleObject( Handle=0x210, Alertable=false, Timeout=null ) => 0
NtClose( Handle=0x210 ) => 0
NtSetEvent( EventHandle=0x200, PrevState=null ) => 0
NtWaitForSingleObject( Handle=0x200, Alertable=false, Timeout=null ) => 0
Access violation at 00000000: Write to 00000000 (first chance)
Access violation at 00000000: Write to 00000000 (first chance)
Access violation at 00443D58: Write to FEEEFEEE (first chance)
NtQueryInformationProcess( ProcessHandle=-1, ProcessInformationClass=0x22 [ProcessExecuteFlags], ProcessInformation=0x41af3fc, Length=4, ReturnLength=null ) => 0
NtQueryInformationProcess( ProcessHandle=-1, ProcessInformationClass=0x22 [ProcessExecuteFlags], ProcessInformation=0x405f564, Length=4, ReturnLength=null ) => 0
NtQueryInformationProcess( ProcessHandle=-1, ProcessInformationClass=0x24 [ProcessCookie], ProcessInformation=0x405f458, Length=4, ReturnLength=null ) => 0
NtQueryInformationProcess( ProcessHandle=-1, ProcessInformationClass=0x24 [ProcessCookie], ProcessInformation=0x41af2f0, Length=4, ReturnLength=null ) => 0
NtQueryInformationProcess( ProcessHandle=-1, ProcessInformationClass=7 [ProcessDebugPort], ProcessInformation=0x405f3d4, Length=4, ReturnLength=null ) => 0
NtQueryInformationProcess( ProcessHandle=-1, ProcessInformationClass=7 [ProcessDebugPort], ProcessInformation=0x41af26c, Length=4, ReturnLength=null ) => 0
NtQueryInformationProcess( ProcessHandle=-1, ProcessInformationClass=0x22 [ProcessExecuteFlags], ProcessInformation=0xf4f740, Length=4, ReturnLength=null ) => 0
Access violation at 74FFCB49: Write to 00000000 (last chance)
Access violation at 74FFCB49: Write to 00000000 (last chance)
NtQueryInformationProcess( ProcessHandle=-1, ProcessInformationClass=0x24 [ProcessCookie], ProcessInformation=0xf4f634, Length=4, ReturnLength=null ) => 0
NtQueryVirtualMemory( ProcessHandle=-1, BaseAddress=0xfeeefeee, MemoryInformationClass=0 [MemoryBasicInformation], MemoryInformation=0xf4f54c, Length=0x1c, ReturnLength=null ) => 0xc000000d [87 'Параметр задан неверно.']
NtQueryInformationProcess( ProcessHandle=-1, ProcessInformationClass=7 [ProcessDebugPort], ProcessInformation=0xf4f5b0, Length=4, ReturnLength=null ) => 0
Access violation at 00443D58: Write to FEEEFEEE (last chance)
Thread 5236 exit code: 3221225477
Thread 6408 exit code: 3221225477
Thread 6184 exit code: 3221225477
Thread 6776 exit code: 3221225477
Thread 2560 exit code: 3221225477
Thread 4740 exit code: 3221225477
Thread 6980 exit code: 3221225477
Thread 4956 exit code: 3221225477
Thread 4700 exit code: 3221225477
Thread 5272 exit code: 3221225477
Process 3424 exit code: 3221225477

Complete log

Work-around:

add one of these lines after write
yield cb => sp.drain(cb)
yield cb => setImmediate(cb, 0)

[reconbot]

Version 4.0.6 is Released please give it a try and let me know if it fixes this.

[Zensey]

No,
still the same

[Zensey]

I've found out that if move callback.Call in EIO_AfterWrite to the place where it was in serialport@3.1.2, then program stops crashing.

Patch:

===================================================================
--- src/serialport.cpp  (revision f5179ada83f7355aff96ff960c0d096f5b1be584)
+++ src/serialport.cpp  (revision )
@@ -312,6 +312,7 @@
   } else {
     argv[0] = Nan::Null();
   }
+  data->callback.Call(1, argv);

   if (data->offset < data->bufferLength && !data->errorString[0]) {
     // We're not done with this baton, so throw it right back onto the queue.
@@ -335,8 +336,6 @@

   // remove this one from the list
   queuedWrite->remove();
-
-  data->callback.Call(1, argv);

   // If there are any left, start a new thread to write the next one.
   if (!write_queue.empty()) {

[Zensey]

I've been testing this patch under Windows and Linux (Banana Pi) all this day.
I don't know how it works, but everything is OK now.

[Zensey]

I think problem is caused by patch #808.
I added printfs to Write, EIO_Write, EIO_AfterWrite and run the test.
As you can see in end of log
data->fd is being changed somehow from its original value 0x260 to 0xf871a0a0.

newQForFD > fd=258
qForFD > fd=258
[2016-11-15 16:04:24.557] [INFO] test - > 1
Write >
qForFD > fd=258
Write > uv_queue_work
Write > uv_queue_work &queuedWrite->req f66d5e10
EIO_Write>
EIO_Write> Exit, *req=f66d5e10
EIO_AfterWrite> *req f66d5e10
qForFD > fd=258
EIO_AfterWrite> calback.Call data->callback=f67593c0
[2016-11-15 16:04:24.562] [INFO] test - > 2
Write >
qForFD > fd=258
Write > uv_queue_work
Write > uv_queue_work &queuedWrite->req f66d5860
EIO_Write>
EIO_AfterWrite> !write_queue.empty()
EIO_AfterWrite> uv_queue_work &nextQueuedWrite->req=f66d5860
EIO_AfterWrite> delete data * f8719c60
EIO_AfterWrite> delete queuedWrite * f66d5e10
EIO_Write>
EIO_Write> Exit, *req=f66d5860
EIO_AfterWrite> *req f66d5860
qForFD > fd=258
EIO_AfterWrite> calback.Call data->callback=f67593e0
[2016-11-15 16:04:24.562] [INFO] test - > 3
Write >
qForFD > fd=258
Write > uv_queue_work
Write > uv_queue_work &queuedWrite->req f66d5930
EIO_Write>
EIO_AfterWrite> !write_queue.empty()
EIO_AfterWrite> uv_queue_work &nextQueuedWrite->req=f66d5930
EIO_AfterWrite> delete data * f67920b0
EIO_Write>
EIO_AfterWrite> delete queuedWrite * f66d5860
EIO_Write> Exit, *req=f66d5860
EIO_AfterWrite> *req f66d5860
qForFD > fd=f871a0a0
!q
EIO_Write> Exit, *req=f66d5930
EIO_AfterWrite> *req f66d5930
qForFD > fd=258
EIO_AfterWrite> calback.Call data->callback=f67592e0
[2016-11-15 16:04:24.567] [ERROR] test - error> TypeError: There's no write queue for that file descriptor (after write)!
    at TypeError (native)
EIO_AfterWrite> delete data * f8719c60
EIO_AfterWrite> delete queuedWrite * f66d5930
EIO_Write> Exit, *req=f66d5930
EIO_AfterWrite> *req f66d5930
qForFD > fd=f871c520
!q
[2016-11-15 16:04:24.570] [ERROR] test - uncaughtException> TypeError: There's no write queue for that file descriptor (after write)!
    at TypeError (native)

[reconbot]

Can you try 5.0.0-beta5?

[reconbot]

Other reports have confirmed this is fixed.