dynarithmic / twain_library-java

Apache License 2.0
11 stars 4 forks source link

Various errors with the high level Java API #13

Closed mclem closed 22 hours ago

mclem commented 2 weeks ago

Hello,

I am trying to the high level Java API but I cannot make it work consistently (my program is often stuck in the TwainSource.acquire()method). The target device is an Epson Perfection V600 but in my local development environment I am using the TWAIN2 sample DS. The DTWDEMO.exe always works flawlessly so I suspect the problems are in the Java API or the JNI layer.

Here are some of the problems I encountered:

  1. Acquiring a PDF file

With DTWDEMO: twain_pdf_demo.log Running PDFDemo.java: twain_pdf_jni.log

When I click on "Scan" the UI becomes stuck. I cannot close it by clicking on "Cancel".

There are a lot of errors and exceptions in the JNI log. I also found these strange values in the log:

TW_MEMREF is TW_IMAGELAYOUT:
{
    Frame=0,0-0,0
    DocmentNumber=4294967295
    PageNumber=4294967295
    FrameNumber=4294967295
}

[2024-08-30 11:45:06] Thread [23412] Output: return code from DSM=1 (TWRC_FAILURE)

I noticed that the TW_FRAME.isFrameValid() method inacurrately returns true when all values are set to 0, because of the comparison with Double.MIN_VALUE: image If I define a frame size (ts.getAcquireCharacteristics().getPagesSupportOptions().getFrame().setRight(6).setBottom(10);) then it looks like the acquisition goes further but it does not complete too: twain_pdf_jni+frame.log

=> It seems impossible to acquire a file (even a simple BMP with TinyApplication.java)

  1. Acquiring to buffer

I am able to run the BufferAcquisitionDemo.java demo, however if I add a logger and enable it with twainSession.enableLogging(true) then the program stays stuck in the acquire method: twain_buf_jni+logging.log Now if I disable logging just before calling acquire the demo works correctly: twain_buf_jni+notlogging.log

=> It is possible to acquire to buffer, but not if I collect logs

  1. With the EPSON V600

I have not been able to make a lot of tests yet, but I noticed that:

dynarithmic commented 2 weeks ago

Thanks for the detailed message.

It's strange why the sample source would get stuck like this. I have not had an issue with the sample TWAIN data source.

As to the logs and the amount of information generated, there are a lot of calls to DTWAIN_IsTwainMsg which can be removed by specifying the appropriate logging flags. You can adjust the java source code here and remove the SHOW_ISTWAINMSG flag in the logging options (probably by doing a LOGALL & ~SHOW_ISTWAINMSG, if I have my boolean logic right).

The log files should be much smaller after doing this, but still retain the call stack and other TWAIN traffic.

Given this, try the following suggestions:

1) Use the latest version 5.4.8 of the DTWAIN libraries (you will also need to use the text resources, since there have been changes).

2) You can also try the library in the development branch to see if any of the updates there makes a difference.

3) You can also try the unreleased version 5.5 of the DTWAIN DLL's, and the updated text resources.

I believe the exception error you received was addressed in the experimental 5.5 version, or if not may have been addressed in 5.4.8.

mclem commented 2 weeks ago

Hi, and thanks for the reply,

I made the following modifications:

Following are my observations, considering:

A) Acquiring to file with TinyApplication: A1) Run, wait for the TWAIN UI, click "Cancel" => the demo completes normally with no acquisition, DTWAIN_AcquireFile returns 1002 A2) Run, wait for the TWAIN UI, click "Scan" => the UI is stuck (cannot close or cancel), DTWAIN_AcquireFile never returns A3) Retry A2) with logging => the UI is stuck (cannot close or cancel), DTWAIN_AcquireFile never returns => twain_jni_A3.log A4) Retry A2) with callback => after the UI opens I see: onGeneralError, onGeneralError

B) Acquiring to memory with BufferedAcquisitionDemo: B1) Run, wait for the TWAIN UI, click "Cancel => the demo completes normally with no acquisition, DTWAIN_AcquireBuffered returns no image bytes B2) Run, wait for the TWAIN UI, click "Scan" then "Cancel => the demo completes normally with one acquisition, DTWAIN_AcquireBuffered returns the image bytes B3) Retry B2) with logging => the UI is stuck (cannot close or cancel), DTWAIN_AcquireBuffered never returns => twain_jni_B3.log B4) Retry B2) with logging stopped => the demo completes normally with one acquisition, DTWAIN_AcquireBuffered returns the image bytes => twain_jni_B4.log B5) Retry B2) with callback => after the UI opens I see: onGeneralError, onGeneralError, onGeneralError, onProcessDIBAccepted, onUIOpened, onAcquireStarted B6) Retry B2) with logging and callback => after the UI opens I see: onGeneralError B5) Retry B2) with logging stopped and callback => after the UI opens I see: onGeneralError, onGeneralError, onGeneralError, onProcessDIBAccepted, onUIOpened, onAcquireStarted

Concerning log file B3:

In summary:

dynarithmic commented 2 weeks ago

1) Please try the latest DLL's in the experimental branch. From looking at the logs, you are probably not running the latest DLL's that contain various fixes to the opening of a Source, plus the file system changes. The "DTWAIN Exception Error" messages also should be minimized, if not completely gone.

2) As to the "file system", it is actually the internal TWAIN file system that some sources support (usually high-end duplex scanners). I tested with a sample Kodak virtual scanner that emulates the file system, and you should not be receiving the exception error messages if your scanner doesn't support it.

3) I tried the "SimpleLoggingDemo.java", and found no issues with logging to the Java console. The entire log when I run the program is here: SimpleLoggingDemo.log

4) I suggest turning off the LoggingOptions.DECODE_TWEVENT to further reduce the size of the log. You would do this similar to how you turned the SHOW_ISTWAINMSG logging off.

5) If possible, can you attach your entire Java program that you are running? This is to ensure that I have the exact program that is giving the issue.

6) The logs just seem to stop right in the middle of an operation. What happens if you only log to the console and not a file?

mclem commented 2 weeks ago

Hi,

  1. OK, I initially downloaded the 5.5.0 version from twain_library instead of twain_library-source. The logs now show "Internal Build Number: 000"

  2. There are now less exceptions about the file system. For example in the buffered acquisition scenario I do not see "Entering FSGetCamera" anymore.

  3. I also tried to run the SimpleLoggingDemo without changing anything. Comparing your log with mine I found these differences:

    • You have the Sample DS version 2.4.0 whereas I have version 2.5.0
    • In my log, there is no trace of CAP_SUPPORTEDDATS
    • In my log, each callback leads to an exception, e.g.:

      [2024-09-03 10:10:43.426] Thread [34372] To callback:
      DTWAIN Message(HWND = 00000000, MSG = 50372, Notification code = 1038, LPARAM = -1058
      
      [2024-09-03 10:10:43.427] Thread [34372] **** DTWAIN Exception Error ****.  Module: DTWAIN_EnumCamerasEx
    • My log nevers resumes as the program is stuck in the acquire method
  4. Here are 4 less verbose logs where I also compacted conse

    There are a lot of errors about callbacks in the files where the acquisition is logged

  5. Here you will find the programs that I used to generate these logs: https://github.com/mclem/twain_library-java/commit/ebf7520da79ddfee3d8e7e0a56861825e31445e4

  6. If I log to the console I have the complete log messages as expected. It looks like a buffer is not flushed when stopping logs to file, so some lines are lost. I completed my log files with the additional lines from the console.

dynarithmic commented 2 weeks ago

1) There are newer versions of the JNI DLL's in the development repo. I believe they should address the DTWAIN Exception messages you are seeing now.

2) In newlog.log, there are 4 places where CAP_SUPPORTEDDATS is being processed:

  Line 2145     CAP_SUPPORTEDDATS
  Line 2330     Array[10] = CAP_SUPPORTEDDATS
  Line 3379     Cap=CAP_SUPPORTEDDATS
  Line 3420     Cap=CAP_SUPPORTEDDATS

3) Since it seems that console logging works and file logging does not work, this seems to be a Java (and not a JNI) issue. The JNI code does not know that Java is writing to the console or a file. The JNI layer calls the Java method TwainLogger.logMessage with the log message, and from there Java takes over.

Note that TwainLogger keeps an array of TwainLoggerProc instances, and both TwainConsoleLogger and TwainFileLogger are derived from TwainLoggerProc. So there is something going on, at least in your environment, that is causing TwainFileLogger to cause an issue.

I think you should debug what is going on in TwainFileLogger, since I cannot duplicate the error. Quite possibly, you can derive your own logger from TwainLoggerProc and perform the file writing in a different way than what is presented in TwainFileLogger.java .

mclem commented 2 weeks ago
  1. I am indeed using the dtwainjni32u DLL from https://github.com/dynarithmic/twain_library-java/blob/development/JNI_DLL/32bit/dll32.zip => version 1.0.4.0, modified 01/09/2024 16:55.

  2. We can forget about CAP_SUPPORTEDDATS, I missed it when I tried to compare both log files line by line. The only meaningful difference seems to be that callbacks never work in my environment according to my logs.

  3. About the TwainFileLogger missing contents, the problem is simply that it uses a FileWriter which is buffered. Thus when the Log method receives a messages and calls logFile.write(sMsg + "\n");, the line is not directly appended to the file. Just for testing, I added a call to FileWriter.flush after writing each message and now the log file is complete: https://github.com/dynarithmic/twain_library-java/commit/f28a4a4dd34adcbbaa733d19089c5685c6aedd30

Some more observations:

In summary, in my environement (Eclipse Adoptium JDK 17.0.11.9) :

dynarithmic commented 2 weeks ago

Thanks for the detailed response.

I will look at the changes you made on the Java side with the TwainFileLogger.

The logger in general is really run purely by callback method on the JNI side (note the calls to DTWAIN_SetCallback in the JNI code). There is actually no direct call to DTWAIN_SetTwainLog to set up the logging. The idea is that the JNI code should only send the message string back to Java, and let Java handle what it should do with the string.

Of course, you can go directly to the native method of setting the twain log, and that should work if you want to log to a file. However you should then refer to the general DTWAIN documentation on DTWAIN_SetTwainLog, as the flags may differ slightly from what you see in Java.

Also, I am looking at the UIOPENING notification, and there definitely looks like there is an issue that I need to fix in the DTWAIN library to clear up the confusion between that notification and other notifications. The Java code is simply showing the symptoms of this.

Since version 5.5 of DTWAIN is still in development phase, I will try and get updates to the library, and then you can get the latest from the development repo.

dynarithmic commented 2 weeks ago

I didn't add the TwainFileLogger changes you mentioned just yet -- I want to make sure that the notifications you were not getting are now being received.

mclem commented 2 weeks ago

Hi

The logger in general is really run purely by callback method on the JNI side (note the calls to DTWAIN_SetCallback in the JNI code). There is actually no direct call to DTWAIN_SetTwainLog to set up the logging. The idea is that the JNI code should only send the message string back to Java, and let Java handle what it should do with the string.

OK, I had the idea to play with DTWAIN_SetTwainLog because I saw this line in TwainLogger.java

I now have better results with the experimental 5.5.0 build 001 so I have updated and simplified my test programs:: https://github.com/dynarithmic/twain_library-java/commit/703f72494c1487f202aea73a7690b1fdc3c2308d In summary:

Here are the logs:

However there seem to be some remaining problems:

Thanks for all the updates :)

dynarithmic commented 2 weeks ago

I looked at your logs, and see the "Callback did not work..." message. That message is generated within the DTWAIN code here.

I took your code and ran it against the TWAIN source 2.4. I do not get these messages, indicating that possibly something is happening between JNI and Java that is causing an exception to be thrown in your environment. Not sure, since it looks like all of the logging messages for TN_UIOPENING are being written to your log file, but some quirk is throwing an exception on your end.

The exception doesn't seem to be "harmful", just annoying.

Here is my log file: my_AcquireBuffered.log

I am running JRE 1.8.0_34.

To this, I will make changes to only log the exception error if the MISCELLANEOUS flag is on for logging. Right now, you will always receive this message if an exception is thrown.

Thanks for the information on the bit depth setting. I will also make changes there to test for the default bit depth of 0.

mclem commented 1 week ago

I think there is some kind of conflict between the "basic" JNI callback (DTWAINCallback / TwainCallback.onTwainEvent) and the "logger" JNI callback (DTWAINLoggerCallback / TwainSession.logEvent). In Java 8 everything works correctly but starting from Java 9 the basic callback does not work anymore if Java logs are enabled.

I recompiled the JNI dll locally with some printing statements to try to find an explanation. Here is a gdb trace that I collected when the callback fails if it helps:

Thread 4 received signal SIGSEGV, Segmentation fault.
0x0000000074e2cb3c in jvm!AsyncGetCallTrace () from C:\DEV\JDK\jdk-9.0.4\bin\server\jvm.dll
(gdb) bt
#0  0x0000000074e2cb3c in jvm!AsyncGetCallTrace () from C:\DEV\JDK\jdk-9.0.4\bin\server\jvm.dll
No symbol table info available.
#1  0x00007ffaba60cb5a in JNIEnv_::CallStaticIntMethod (this=0x2d135ccf1d8, clazz=0x2d1663cb358, methodID=0x2d166d59338) at C:/Program Files/Eclipse Adoptium/jdk-17.0.9.9-hotspot/include/jni.h:1451
        args = 0xe8400fb418 "╗\v"
        result = 0
#2  0x00007ffaba571a2c in JavaCallback::DTWAINCallback (w=3003, l=3098388890768, This=1732340928) at ../DTWAINJavaAPI.cpp:217
        sGeneralErrors = std::set with 1 element = {[0] = 1038}
        pCallback = std::shared_ptr<JavaCallback> (use count 3, weak count 0) = {get() = 0x2d167416cc0}
        iter = {first = "TwainMessageListener", second = {m_jClassName = "com/dynarithmic/twain/highlevel/TwainCallback", m_jFunctionName = "(IJZ)I", m_jFunctionSig = "", m_jCallbackClass = 0x2d1663cb358, m_jCallbackMethodID = 0x2d166d59338}}
        pCallInfo = @0x2d167406180: {m_jClassName = "com/dynarithmic/twain/highlevel/TwainCallback", m_jFunctionName = "(IJZ)I", m_jFunctionSig = "", m_jCallbackClass = 0x2d1663cb358, m_jCallbackMethodID = 0x2d166d59338}
        wrapper = {m_pCallBack = std::shared_ptr<JavaCallback> (use count 3, weak count 0) = {get() = 0x2d167416cc0}}
        pEnv = 0x2d135ccf1d8
        retval = 0
#3  0x00007ffab9e66e04 in DTWAIN_CheckHandles () from C:\DEV\JNI\dtwain64u.dll
No symbol table info available.
#4  0x00007ffab9e6821b in DTWAIN_RemoveCallback () from C:\DEV\JNI\dtwain64u.dll
No symbol table info available.
#5  0x00007ffab9e6bfbd in DTWAIN_WindowProc () from C:\DEV\JNI\dtwain64u.dll
No symbol table info available.
#6  0x00007ffb3cf4ef5c in USER32!CallWindowProcW () from C:\WINDOWS\System32\user32.dll
No symbol table info available.
#7  0x00007ffb3cf4dfbb in USER32!SendMessageW () from C:\WINDOWS\System32\user32.dll
No symbol table info available.
#8  0x00007ffb3cf4d814 in USER32!SendMessageW () from C:\WINDOWS\System32\user32.dll
No symbol table info available.
Backtrace stopped: previous frame inner to this frame (corrupt stack?)

At first I thought it may have something to do with this line, as if I understood correctly the code runs like this:

However commenting out the call to IsSourceValid (I hardcoded FALSE) did not change anything so I must be wrong...

Then I played with the DTWAINLoggerCallback and I found out that if I replace CreateJStringFromCString(pEnv, str) with NULL, the basic callback works again. Maybe some kind of memory leak as some sources suggest that these strings should be freed at some point:

dynarithmic commented 1 week ago

Thanks for the information.

I did some debugging, and I ran using Java 11. I duplicated the issue that you were seeing with the exceptions being thrown instead of having the callback being called. The callbacks do work right before the Source is selected, but from there, they stop working and instead exceptions are thrown when opening the UI, etc.

For a test, I changed the JNI code here in the constructor and created another member function called InitInfo:

JavaCallback::JavaCallback(JNIEnv * pEnv) : JavaAdapter(pEnv)
{
    InitInfo(pEnv);
}

void JavaCallback::InitInfo(JNIEnv* pEnv)
{
    Init(pEnv);
    // Logger and listener callbacks are initialized here
    std::array<std::string, 2> categories = { "TwainLogger", "TwainMessageListener" };
    for (auto& s : categories)
    {
        auto iter = JavaFunctionNameMapInstance::getFunctionMap().find(s);
        auto& callback_info = iter->second;
        auto& callback_fn = iter->second.m_mapFunctions;
        auto& namesig = (*callback_fn.begin()).second;
        auto& jcallback = m_jCallbackInfo.insert({ s, {callback_info.m_className, namesig.funcName, namesig.funcSig} }).first;

        // Get the java class class
        jcallback->second.m_jCallbackClass = pEnv->FindClass(jcallback->second.m_jClassName.c_str());

        // get the method id stored in the class
        jcallback->second.m_jCallbackMethodID = pEnv->GetStaticMethodID(jcallback->second.m_jCallbackClass,
            namesig.funcName.c_str(),
            namesig.funcSig.c_str());
    }
    m_pThisObject = this;
}

Now InitInfo is called right before each call to the callback here.

    pCallback->InitInfo(pEnv);
    if ( !sGeneralErrors.count(w))
    {
        retval = pEnv->CallStaticIntMethod(pCallInfo.m_jCallbackClass, pCallInfo.m_jCallbackMethodID, w, static_cast<jlong>(l),
                                           API_INSTANCE DTWAIN_IsSourceValid(reinterpret_cast<DTWAIN_SOURCE>(l))?TRUE:FALSE);
    }
    else
        retval = pEnv->CallStaticIntMethod(pCallInfo.m_jCallbackClass, pCallInfo.m_jCallbackMethodID, w, 0, FALSE);

From there, the callbacks are now invoked, and the exceptions are now gone. The code always gets the latest pointer to the JVM environment on each call, so that wasn't an issue. As a matter of fact, the environment pointer is stable. The issue is that the class and method id's can change on each call. This is highly unfortunate.

Since a lot of the code right now relies on method ID's to call back to the Java's com.dynarithmic.twain.lowlevel functions, this would mean having to reinitialize the function pointers whenever a call from the JNI side needs to be made. This would be highly inconvenient in terms of efficiency (the function in the JNI code to read and process dtwainjava.info is where the function and class id's are established) just to ensure the class and method ID's are changed.

Admittedly, I don't know if there is a JVM setting that state "don't move my classes once they are loaded" -- maybe something to do with the classloader and/or for some reason, the callback objects were garbage collected? If you know if there is a way to do this, then that would probably solve the problem, at least temporarily until I find a way to better ensure that the class and method id's are loaded whenever a call is made.

dynarithmic commented 1 week ago

After going through the code again, I think it will be ok. There is this function that is called every time a JNI object that mimics the Java low-level object is called.

Basically that function takes the class name, finds the function name and signature in the map that was previously populated, and re-establishes all of the method id and class id info. The issue seems to be that the static methods (logger and callback) were never re-initialized.

I will try and get new JNI DLL's in development.

dynarithmic commented 1 week ago

New commits done here. I tested this with Java 11 and using the AcquireBuffered() program. I didn't come across the issue with the exceptions being thrown.

mclem commented 1 week ago

Admittedly, I don't know if there is a JVM setting that state "don't move my classes once they are loaded" -- maybe something to do with the classloader and/or for some reason, the callback objects were garbage collected? If you know if there is a way to do this, then that would probably solve the problem, at least temporarily until I find a way to better ensure that the class and method id's are loaded whenever a call is made.

According to the following links I understood that if you want to reuse safely a java methodID, you should keep a global reference to its class to avoid it being unloaded:

To test, I replaced this line with the following code and everything seems to work correctly:

jclass tempLocalClassRef = pEnv->FindClass(jcallback->second.m_jClassName.c_str());
jclass globalClassRef = (jclass) pEnv->NewGlobalRef(tempLocalClassRef);
pEnv->DeleteLocalRef(tempLocalClassRef);
jcallback->second.m_jCallbackClass = globalClassRef;

 
 
Also while compiling the JNI layer I noticed a mistake in the javaobjetcaller.h file: https://github.com/dynarithmic/twain_library-java/blob/81ab5544edec62cd06e224caf9bafae3c6304e98/JNI_Source/classes/com/dynarithmic/jnicode/javaobjectcaller.h#L734 It should be getFunctionName instead of GetProductName.

dynarithmic commented 1 week ago

Thanks. I made the correction to the getFunctionName.

From the first document link, I see this:

A field or method ID does not prevent the VM from unloading the class from which the ID has been derived. After the class is unloaded, the method or field ID becomes invalid. The native code, therefore, must make sure to:

keep a live reference to the underlying class, or
recompute the method or field ID

So the second option of recomputing the method ID's is what keeps the other functions from not failing in the current JNI code (except for the logger and callback methods).

I took the code you have for creating the global ref for the logger and callback, and things now work correctly. I will probably use this code for the static methods, and keep the reinitialization code for the other classes.

dynarithmic commented 1 day ago

New commit to master (#17). This should address most of the issues you've seen.

mclem commented 22 hours ago

Hi, I can confirm that everything works correctly with the latest JNI and library DLLs. Thank you so much for the help and quick feedback! 😃