search

AndreasFagschlunger / O2Xfs

Java API for accessing CEN/XFS API, EMV Level 2 Kernel
47 stars 28 forks source link

Problem with allocating memory #75

Closed VitalyEG closed 5 years ago

VitalyEG commented 5 years ago

Hi Andreas! I have a problem with allocating memory. When I installed XFS_SDK330.msi, I saw in registry this information, see below: Снимок I called, as example (it's may be another requests), 14800 requests of "CdmStatusCallable" and I then process stopped. Count of calls depends on size of data stuctures. Here is error of XfsTrace.LOG

18:30:36.189 support call: WFMAllocateBuffer
    actSize: 150 0X00000096
    actFlags: 3 0X00000003
    lppvData: 101709396 0X060FF654
    cproc: 7848 0X00001EA8
    cthread: 4388 0X00001124
18:30:36.189 support call: VirtualBaseAddr
    lpVirtualBase: 1807745024 0X6BC00000
18:30:36.189 support return: WFMAllocateBuffer ERROR: WFS_ERR_OUT_OF_MEMORY
18:30:36.189 support call: WFMMakeResult
    statusCode: -42

And there is log of application: 2019-04-24 18:30:36,189 [main] INFO at.o2xfs.xfs.service.XfsServiceManager - execute: start XfsInfoCommand=STATUS======================== 2019-04-24 18:30:36,189 [main] DEBUG at.o2xfs.xfs.XfsAPI - wfsAsyncGetInfo(HSERVICE, DWORD, Type, DWORD, HWND): hService=1,dwCategory=301,queryDetails=null,dwTimeOut=0,hWnd=72061100 2019-04-24 18:30:36,189 [main] INFO at.o2xfs.xfs.service.XfsServiceManager - execute: end XfsInfoCommand=STATUS 2019-04-24 18:30:36,189 [main] DEBUG at.o2xfs.xfs.service.cmd.XfsCallable - call(): Waiting ... 2019-04-24 18:30:36,189 [MessageHandler] DEBUG at.o2xfs.xfs.util.MessageHandler - callback(int, Buffer): msg=1031,lpWFSResult=at.o2xfs.win32.impl.Win32Buffer@a31785[size=4,address=78F7A905] 2019-04-24 18:30:36,189 [MessageHandler] INFO at.o2xfs.xfs.util.MessageHandler - callback(int, Buffer): xfsMessage=WFS_GETINFO_COMPLETE 2019-04-24 18:30:36,189 [MessageHandler] INFO at.o2xfs.xfs.util.MessageHandler - callback(int, Buffer): before new WFSResult(new Pointer(lpWFSResult)) 2019-04-24 18:30:36,189 [MessageHandler] INFO at.o2xfs.xfs.util.MessageHandler - callback(int, Buffer): before xfsCallback.callback(xfsMessage, wfsResult) 2019-04-24 18:30:36,189 [MessageHandler] INFO at.o2xfs.xfs.service.XfsServiceManager - callback(XFSMessage, WFSResult): msg=WFS_GETINFO_COMPLETE,wfsResult=at.o2xfs.xfs.WFSResult@77b40f[requestID=14770,service=1,timestamp=at.o2xfs.win32.SYSTEMTIME@10ebc97[types=[2019, 4, 3, 24, 18, 30, 36, 0]],result=0,u=at.o2xfs.win32.Union@1f94d9c[size=4,fields={commandCode=0,eventID=0}],buffer=Address: F6AF0F6C, Value: 18E10F6C] 2019-04-24 18:30:36,189 [MessageHandler] DEBUG at.o2xfs.xfs.service.XfsServiceManager - callback(XFSMessage, WFSResult): wfsResult.getRequestID()=14770 2019-04-24 18:30:36,189 [MessageHandler] DEBUG at.o2xfs.xfs.service.EventDispatcher - dispatch(XFSMessage, IXfsEventNotification, WFSResult): xfsMessage=WFS_GETINFO_COMPLETE,eventNotification=at.o2xfs.xfs.service.cmd.XfsCallable@1cee4da,wfsResult=at.o2xfs.xfs.WFSResult@77b40f[requestID=14770,service=1,timestamp=at.o2xfs.win32.SYSTEMTIME@10ebc97[types=[2019, 4, 3, 24, 18, 30, 36, 0]],result=0,u=at.o2xfs.win32.Union@1f94d9c[size=4,fields={commandCode=0,eventID=0}],buffer=Address: F6AF0F6C, Value: 18E10F6C] 2019-04-24 18:30:36,189 [MessageHandler] DEBUG at.o2xfs.xfs.service.cmd.XfsCallable - fireOperationCompleteEvent(WFSResult): wfsResult=at.o2xfs.xfs.WFSResult@77b40f[requestID=14770,service=1,timestamp=at.o2xfs.win32.SYSTEMTIME@10ebc97[types=[2019, 4, 3, 24, 18, 30, 36, 0]],result=0,u=at.o2xfs.win32.Union@1f94d9c[size=4,fields={commandCode=0,eventID=0}],buffer=Address: F6AF0F6C, Value: 18E10F6C] 2019-04-24 18:30:36,189 [MessageHandler] INFO at.o2xfs.xfs.util.MessageHandler - callback(int, Buffer): after xfsCallback.callback(xfsMessage, wfsResult) 2019-04-24 18:30:36,189 [main] INFO at.o2xfs.xfs.service.cdm.CdmStatusCallable - call(): at.o2xfs.xfs.v3_00.cdm.CdmStatus3@1787605[deviceState=ONLINE,safeDoor=CLOSED,dispenser=OK,intermediateStacker=EMPTY,positions={at.o2xfs.xfs.v3_00.cdm.OutputPosition3@107713f[position=CENTER,shutter=CLOSED,positionStatus=EMPTY,transport=OK,transportStatus=EMPTY]},extra={key=value}] 2019-04-24 18:30:36,189 [main] DEBUG at.o2xfs.xfs.service.XfsServiceManager - free(WFSResult): wfsResult=at.o2xfs.xfs.WFSResult@77b40f[requestID=14770,service=1,timestamp=at.o2xfs.win32.SYSTEMTIME@10ebc97[types=[2019, 4, 3, 24, 18, 30, 36, 0]],result=0,u=at.o2xfs.win32.Union@1f94d9c[size=4,fields={commandCode=0,eventID=0}],buffer=Address: F6AF0F6C, Value: 18E10F6C] 2019-04-24 18:30:36,189 [main] DEBUG at.o2xfs.xfs.XfsAPI - wfsFreeResult(WFSResult): wfsResult=at.o2xfs.xfs.WFSResult@77b40f[requestID=14770,service=1,timestamp=at.o2xfs.win32.SYSTEMTIME@10ebc97[types=[2019, 4, 3, 24, 18, 30, 36, 0]],result=0,u=at.o2xfs.win32.Union@1f94d9c[size=4,fields={commandCode=0,eventID=0}],buffer=Address: F6AF0F6C, Value: 18E10F6C] 2019-04-24 18:30:36,189 [main] INFO com.lwo.rwsst.device.emu_xfs.TestMaxCalls4OutOfMemory - main: cnt_rq=14767 dev_status=at.o2xfs.xfs.v3_00.cdm.CdmStatus3@1787605[deviceState=ONLINE,safeDoor=CLOSED,dispenser=OK,intermediateStacker=EMPTY,positions={at.o2xfs.xfs.v3_00.cdm.OutputPosition3@de4d65[position=CENTER,shutter=CLOSED,positionStatus=EMPTY,transport=OK,transportStatus=EMPTY]},extra={key=value}] 2019-04-24 18:30:36,189 [main] INFO at.o2xfs.xfs.service.XfsServiceManager - : (*)execute=at.o2xfs.xfs.service.cmd.XfsInfoCommand@1dca9a2[xfsService=at.o2xfs.xfs.service.cdm.CdmService@1df66b6[logicalName=CDM_BILLS_EMULATION,serviceClass=CDM,hService=1,srvcVersionsRequired=at.o2xfs.xfs.XFSVersionDWORD@ec5519[lowVersion=3.0,highVersion=3.30],srvcVersion=at.o2xfs.xfs.WFSVersion@f7298b[version=3.00,lowVersion=3.10,highVersion=3.30,description=CDM_BILLS_EMULATION,systemStatus=],spiVersion=at.o2xfs.xfs.WFSVersion@8715b5[version=3.00,lowVersion=2.00,highVersion=3.30,description=CDM_BILLS_EMULATION,systemStatus=]],requestId=<null>,category=STATUS,queryDetails=<null>] 2019-04-24 18:30:36,189 [main] INFO at.o2xfs.xfs.service.XfsServiceManager - execute: start XfsInfoCommand=STATUS======================== 2019-04-24 18:30:36,189 [main] DEBUG at.o2xfs.xfs.XfsAPI - wfsAsyncGetInfo(HSERVICE, DWORD, Type, DWORD, HWND): hService=1,dwCategory=301,queryDetails=null,dwTimeOut=0,hWnd=72061100 2019-04-24 18:30:36,189 [main] INFO at.o2xfs.xfs.service.XfsServiceManager - execute: end XfsInfoCommand=STATUS 2019-04-24 18:30:36,189 [main] DEBUG at.o2xfs.xfs.service.cmd.XfsCallable - call(): Waiting ...

Could you help me?

VitalyEG commented 5 years ago

Maybe core O2XFS have a leak of memory on "XfsServiceManager.getInstance().free(wfsResult);".

AndreasFagschlunger commented 5 years ago

Hi @VitalyEG Sorry for the delay! By the way, this is the Issue section of my angular project. But either way, the class you use CdmStatusCallable, doesn't appear in my code anymore. use CdmStatusCommand instead.

But also, your call-Method in should look something like this:

    public CdmStatus3 call() throws XfsException {
        final XfsCommand infoCommand = new XfsInfoCommand<>(cdmService, CdmInfoCommand.STATUS);
        final WFSResult wfsResult = infoCommand.call();
        try {
            final CdmStatus3 result = new CdmStatus3(new CdmStatus3(wfsResult.getResults()));
            if (LOG.isInfoEnabled()) {
                final String method = "call()";
                LOG.info(method, "result=" + result);
            }
            return result;
        } finally {
            if (wfsResult != null) {
                XfsServiceManager.getInstance().free(wfsResult);
            }
        }
    }

There should be a try catch where in the finally-Block it calls the free method. You should see a log entry like this:

2019-04-27 01:07:41,073 DEBUG at.o2xfs.xfs.service.XfsServiceManager [MessageHandler][11] callback(XFSMessage, WFSResult): msg=WFS_GETINFO_COMPLETE,wfsResult=at.o2xfs.xfs.WFSResult@3abd02[requestID=18263,service=1,timestamp=at.o2xfs.win32.SYSTEMTIME@7898f8[types=[2019, 4, 6, 27, 1, 7, 41, 73]],result=0,u=at.o2xfs.win32.Union@1ae7370[size=4,fields={commandCode=302,eventID=302}],buffer=Address: 6BC08D76, Value: 6BC0B018]
...
2019-04-27 01:07:41,073 DEBUG at.o2xfs.xfs.service.XfsServiceManager [main][1] free(WFSResult): wfsResult=at.o2xfs.xfs.WFSResult@3abd02[requestID=18263,service=1,timestamp=at.o2xfs.win32.SYSTEMTIME@7898f8[types=[2019, 4, 6, 27, 1, 7, 41, 73]],result=0,u=at.o2xfs.win32.Union@1ae7370[size=4,fields={commandCode=302,eventID=302}],buffer=Address: 6BC08D76, Value: 6BC0B018]

I started a similar test like you and I'm at request ID 58879 without issues.

2019-04-27 01:19:44,590 DEBUG at.o2xfs.xfs.service.XfsServiceManager [MessageHandler][11] callback(XFSMessage, WFSResult): msg=WFS_GETINFO_COMPLETE,wfsResult=at.o2xfs.xfs.WFSResult@1181ff4[requestID=58879,service=1,timestamp=at.o2xfs.win32.SYSTEMTIME@1cb53e1[types=[2019, 4, 6, 27, 1, 19, 44, 590]],result=0,u=at.o2xfs.win32.Union@1308c24[size=4,fields={commandCode=302,eventID=302}],buffer=Address: 6BC08D36, Value: 6BC0B018]

VitalyEG commented 5 years ago

Here is my test: for (int i = 0; i < 20000; i++) { CdmStatus3 status = new CdmStatusCommand((CdmService) xfsService).call(); LOG.info(method, "cnt_rq=" + i + " dev_status=" + status.toString()); }

Here is my CdmStatusCallable: `package at.o2xfs.xfs.service.cdm;

import java.util.concurrent.Callable;

import at.o2xfs.xfs.v3_00.cdm.CdmStatus3; import at.o2xfs.log.Logger; import at.o2xfs.log.LoggerFactory; import at.o2xfs.xfs.WFSResult; import at.o2xfs.xfs.XfsException; import at.o2xfs.xfs.cdm.CdmInfoCommand; import at.o2xfs.xfs.service.XfsServiceManager; import at.o2xfs.xfs.service.cmd.XfsInfoCommand;

public class CdmStatusCallable implements Callable {

private static final Logger LOG = LoggerFactory.getLogger(CdmStatusCallable.class);

private final CdmService cdmService;

public CdmStatusCallable(final CdmService cdmService) { if (cdmService == null) { throw new IllegalArgumentException("cdmService must not be null"); } this.cdmService = cdmService; }

@Override public CdmStatus3 call() throws XfsException { CdmStatus3 result = null; XfsInfoCommand command = new XfsInfoCommand(cdmService, CdmInfoCommand.STATUS); WFSResult wfsResult = null; try { wfsResult = command.call(); result = new CdmStatus3(new CdmStatus3(wfsResult.getResults())); if (LOG.isInfoEnabled()) { LOG.info("call()", result); } } finally { if (wfsResult != null) { XfsServiceManager.getInstance().free(wfsResult); } } return result; } }`

And I changed my test from CdmStatusCallable to CdmStatusCommand I got other exception: 2019-04-28 21:38:44,873 [main] INFO at.o2xfs.xfs.service.XfsServiceManager - execute: start XfsInfoCommand=STATUS======================== 2019-04-28 21:38:44,873 [main] DEBUG at.o2xfs.xfs.XfsAPI - wfsAsyncGetInfo(HSERVICE, DWORD, Type, DWORD, HWND): hService=1,dwCategory=301,queryDetails=null,dwTimeOut=0,hWnd=6C030200 2019-04-28 21:38:44,873 [main] INFO at.o2xfs.xfs.service.XfsServiceManager - execute: end XfsInfoCommand=STATUS 2019-04-28 21:38:44,873 [main] DEBUG at.o2xfs.xfs.service.cmd.XfsCallable - call(): Waiting ... 2019-04-28 21:38:44,874 [MessageHandler] DEBUG at.o2xfs.xfs.util.MessageHandler - callback(int, Buffer): msg=1031,lpWFSResult=at.o2xfs.win32.impl.Win32Buffer@19e8128[size=4,address=E8F6ED05] 2019-04-28 21:38:44,874 [MessageHandler] INFO at.o2xfs.xfs.util.MessageHandler - callback(int, Buffer): xfsMessage=WFS_GETINFO_COMPLETE 2019-04-28 21:38:44,874 [MessageHandler] INFO at.o2xfs.xfs.util.MessageHandler - callback(int, Buffer): before new WFSResult(new Pointer(lpWFSResult)) 2019-04-28 21:38:44,874 [MessageHandler] INFO at.o2xfs.xfs.util.MessageHandler - callback(int, Buffer): before xfsCallback.callback(xfsMessage, wfsResult) 2019-04-28 21:38:44,874 [MessageHandler] INFO at.o2xfs.xfs.service.XfsServiceManager - callback(XFSMessage, WFSResult): msg=WFS_GETINFO_COMPLETE,wfsResult=at.o2xfs.xfs.WFSResult@40edf1[requestID=14069,service=1,timestamp=at.o2xfs.win32.SYSTEMTIME@1964053[types=[2019, 4, 0, 28, 21, 38, 44, 0]],result=0,u=at.o2xfs.win32.Union@14e2540[size=4,fields={commandCode=0,eventID=0}],buffer=Address: F6EF0B6C, Value: 182E0C6C] 2019-04-28 21:38:44,874 [MessageHandler] DEBUG at.o2xfs.xfs.service.XfsServiceManager - callback(XFSMessage, WFSResult): wfsResult.getRequestID()=14069 2019-04-28 21:38:44,874 [MessageHandler] DEBUG at.o2xfs.xfs.service.EventDispatcher - dispatch(XFSMessage, IXfsEventNotification, WFSResult): xfsMessage=WFS_GETINFO_COMPLETE,eventNotification=at.o2xfs.xfs.service.cmd.XfsCallable@aa7321,wfsResult=at.o2xfs.xfs.WFSResult@40edf1[requestID=14069,service=1,timestamp=at.o2xfs.win32.SYSTEMTIME@1964053[types=[2019, 4, 0, 28, 21, 38, 44, 0]],result=0,u=at.o2xfs.win32.Union@14e2540[size=4,fields={commandCode=0,eventID=0}],buffer=Address: F6EF0B6C, Value: 182E0C6C] 2019-04-28 21:38:44,874 [MessageHandler] DEBUG at.o2xfs.xfs.service.cmd.XfsCallable - fireOperationCompleteEvent(WFSResult): wfsResult=at.o2xfs.xfs.WFSResult@40edf1[requestID=14069,service=1,timestamp=at.o2xfs.win32.SYSTEMTIME@1964053[types=[2019, 4, 0, 28, 21, 38, 44, 0]],result=0,u=at.o2xfs.win32.Union@14e2540[size=4,fields={commandCode=0,eventID=0}],buffer=Address: F6EF0B6C, Value: 182E0C6C] 2019-04-28 21:38:44,874 [MessageHandler] INFO at.o2xfs.xfs.util.MessageHandler - callback(int, Buffer): after xfsCallback.callback(xfsMessage, wfsResult) 2019-04-28 21:38:44,874 [main] DEBUG at.o2xfs.xfs.service.XfsServiceManager - free(WFSResult): wfsResult=at.o2xfs.xfs.WFSResult@40edf1[requestID=14069,service=1,timestamp=at.o2xfs.win32.SYSTEMTIME@1964053[types=[2019, 4, 0, 28, 21, 38, 44, 0]],result=0,u=at.o2xfs.win32.Union@14e2540[size=4,fields={commandCode=0,eventID=0}],buffer=Address: F6EF0B6C, Value: 182E0C6C] 2019-04-28 21:38:44,874 [main] DEBUG at.o2xfs.xfs.XfsAPI - wfsFreeResult(WFSResult): wfsResult=at.o2xfs.xfs.WFSResult@40edf1[requestID=14069,service=1,timestamp=at.o2xfs.win32.SYSTEMTIME@1964053[types=[2019, 4, 0, 28, 21, 38, 44, 0]],result=0,u=at.o2xfs.win32.Union@14e2540[size=4,fields={commandCode=0,eventID=0}],buffer=Address: F6EF0B6C, Value: 182E0C6C] 2019-04-28 21:38:44,874 [main] INFO com.lwo.rwsst.device.emu_xfs.TestMaxCalls4OutOfMemory - main: cnt_rq=14066 dev_status=at.o2xfs.xfs.v3_00.cdm.CdmStatus3@f7a555[deviceState=ONLINE,safeDoor=CLOSED,dispenser=OK,intermediateStacker=EMPTY,positions={at.o2xfs.xfs.v3_00.cdm.OutputPosition3@b65be0[position=CENTER,shutter=CLOSED,positionStatus=EMPTY,transport=OK,transportStatus=EMPTY]},extra={key=value}] 2019-04-28 21:38:44,875 [main] INFO at.o2xfs.xfs.service.XfsServiceManager - : (*)execute=at.o2xfs.xfs.service.cmd.XfsInfoCommand@1bb3a7d[xfsService=at.o2xfs.xfs.service.cdm.CdmService@1df66b6[logicalName=CDM_BILLS_EMULATION,serviceClass=CDM,hService=1,srvcVersionsRequired=at.o2xfs.xfs.XFSVersionDWORD@ec5519[lowVersion=3.0,highVersion=3.30],srvcVersion=at.o2xfs.xfs.WFSVersion@f7298b[version=3.00,lowVersion=3.10,highVersion=3.30,description=CDM_BILLS_EMULATION,systemStatus=],spiVersion=at.o2xfs.xfs.WFSVersion@8715b5[version=3.00,lowVersion=2.00,highVersion=3.30,description=CDM_BILLS_EMULATION,systemStatus=]],requestId=<null>,category=STATUS,queryDetails=<null>] 2019-04-28 21:38:44,875 [main] INFO at.o2xfs.xfs.service.XfsServiceManager - execute: start XfsInfoCommand=STATUS======================== 2019-04-28 21:38:44,875 [main] DEBUG at.o2xfs.xfs.XfsAPI - wfsAsyncGetInfo(HSERVICE, DWORD, Type, DWORD, HWND): hService=1,dwCategory=301,queryDetails=null,dwTimeOut=0,hWnd=6C030200 2019-04-28 21:38:44,875 [main] INFO at.o2xfs.xfs.service.XfsServiceManager - execute: end XfsInfoCommand=STATUS 2019-04-28 21:38:44,875 [main] DEBUG at.o2xfs.xfs.service.cmd.XfsCallable - call(): Waiting ... 2019-04-28 21:38:44,875 [MessageHandler] DEBUG at.o2xfs.xfs.util.MessageHandler - callback(int, Buffer): msg=1031,lpWFSResult=at.o2xfs.win32.impl.Win32Buffer@8a3491[size=4,address=E8F6ED05] 2019-04-28 21:38:44,875 [MessageHandler] INFO at.o2xfs.xfs.util.MessageHandler - callback(int, Buffer): xfsMessage=WFS_GETINFO_COMPLETE 2019-04-28 21:38:44,875 [MessageHandler] INFO at.o2xfs.xfs.util.MessageHandler - callback(int, Buffer): before new WFSResult(new Pointer(lpWFSResult)) 2019-04-28 21:38:44,875 [MessageHandler] INFO at.o2xfs.xfs.util.MessageHandler - callback(int, Buffer): before xfsCallback.callback(xfsMessage, wfsResult) 2019-04-28 21:38:44,876 [MessageHandler] INFO at.o2xfs.xfs.service.XfsServiceManager - callback(XFSMessage, WFSResult): msg=WFS_GETINFO_COMPLETE,wfsResult=at.o2xfs.xfs.WFSResult@3b4da3[requestID=14070,service=1,timestamp=at.o2xfs.win32.SYSTEMTIME@1e8458d[types=[2019, 4, 0, 28, 21, 38, 44, 0]],result=0,u=at.o2xfs.win32.Union@57f30e[size=4,fields={commandCode=0,eventID=0}],buffer=Address: F6EF0B6C, Value: 182D0C6C] 2019-04-28 21:38:44,876 [MessageHandler] DEBUG at.o2xfs.xfs.service.XfsServiceManager - callback(XFSMessage, WFSResult): wfsResult.getRequestID()=14070 2019-04-28 21:38:44,876 [MessageHandler] DEBUG at.o2xfs.xfs.service.EventDispatcher - dispatch(XFSMessage, IXfsEventNotification, WFSResult): xfsMessage=WFS_GETINFO_COMPLETE,eventNotification=at.o2xfs.xfs.service.cmd.XfsCallable@e9aca,wfsResult=at.o2xfs.xfs.WFSResult@3b4da3[requestID=14070,service=1,timestamp=at.o2xfs.win32.SYSTEMTIME@1e8458d[types=[2019, 4, 0, 28, 21, 38, 44, 0]],result=0,u=at.o2xfs.win32.Union@57f30e[size=4,fields={commandCode=0,eventID=0}],buffer=Address: F6EF0B6C, Value: 182D0C6C] 2019-04-28 21:38:44,876 [MessageHandler] DEBUG at.o2xfs.xfs.service.cmd.XfsCallable - fireOperationCompleteEvent(WFSResult): wfsResult=at.o2xfs.xfs.WFSResult@3b4da3[requestID=14070,service=1,timestamp=at.o2xfs.win32.SYSTEMTIME@1e8458d[types=[2019, 4, 0, 28, 21, 38, 44, 0]],result=0,u=at.o2xfs.win32.Union@57f30e[size=4,fields={commandCode=0,eventID=0}],buffer=Address: F6EF0B6C, Value: 182D0C6C] 2019-04-28 21:38:44,876 [MessageHandler] INFO at.o2xfs.xfs.util.MessageHandler - callback(int, Buffer): after xfsCallback.callback(xfsMessage, wfsResult) 2019-04-28 21:38:44,876 [main] DEBUG at.o2xfs.xfs.util.XfsConstants - valueOf(long, Class<E>): Undefined at.o2xfs.xfs.cdm.Position constant: 14070 2019-04-28 21:38:44,876 [main] DEBUG at.o2xfs.xfs.service.XfsServiceManager - free(WFSResult): wfsResult=at.o2xfs.xfs.WFSResult@3b4da3[requestID=14070,service=1,timestamp=at.o2xfs.win32.SYSTEMTIME@1e8458d[types=[2019, 4, 0, 28, 21, 38, 44, 0]],result=0,u=at.o2xfs.win32.Union@57f30e[size=4,fields={commandCode=0,eventID=0}],buffer=Address: F6EF0B6C, Value: 182D0C6C] 2019-04-28 21:38:44,876 [main] DEBUG at.o2xfs.xfs.XfsAPI - wfsFreeResult(WFSResult): wfsResult=at.o2xfs.xfs.WFSResult@3b4da3[requestID=14070,service=1,timestamp=at.o2xfs.win32.SYSTEMTIME@1e8458d[types=[2019, 4, 0, 28, 21, 38, 44, 0]],result=0,u=at.o2xfs.win32.Union@57f30e[size=4,fields={commandCode=0,eventID=0}],buffer=Address: F6EF0B6C, Value: 182D0C6C] 2019-04-28 21:38:44,877 [main] ERROR at.o2xfs.xfs.service.XfsServiceManager - free(WFSResult): Error freeing WFSResult: at.o2xfs.xfs.WFSResult@3b4da3[requestID=14070,service=1,timestamp=at.o2xfs.win32.SYSTEMTIME@1e8458d[types=[2019, 4, 0, 28, 21, 38, 44, 0]],result=0,u=at.o2xfs.win32.Union@57f30e[size=4,fields={commandCode=0,eventID=0}],buffer=Address: F6EF0B6C, Value: 182D0C6C] at.o2xfs.xfs.XfsServiceException: INVALID_RESULT(-28) at at.o2xfs.xfs.XfsServiceExceptionFactory.throwException(XfsServiceExceptionFactory.java:51) at at.o2xfs.xfs.XfsException.throwFor(XfsException.java:92) at at.o2xfs.xfs.XfsAPI.wfsFreeResult(XfsAPI.java:252) at at.o2xfs.xfs.service.XfsServiceManager.free(XfsServiceManager.java:385) at at.o2xfs.xfs.service.ReflectiveInfoCommand.call(ReflectiveInfoCommand.java:72) at com.lwo.rwsst.device.emu_xfs.TestMaxCalls4OutOfMemory.main(TestMaxCalls4OutOfMemory.java:41) Exception in thread "main" java.lang.RuntimeException: java.lang.reflect.InvocationTargetException at at.o2xfs.xfs.service.ReflectiveFactory.createResult(ReflectiveFactory.java:54) at at.o2xfs.xfs.service.ReflectiveFactory.doCreate(ReflectiveFactory.java:44) at at.o2xfs.xfs.service.ReflectiveFactory.create(ReflectiveFactory.java:97) at at.o2xfs.xfs.service.ReflectiveInfoCommand.call(ReflectiveInfoCommand.java:70) at com.lwo.rwsst.device.emu_xfs.TestMaxCalls4OutOfMemory.main(TestMaxCalls4OutOfMemory.java:41) Caused by: java.lang.reflect.InvocationTargetException at sun.reflect.GeneratedConstructorAccessor4.newInstance(Unknown Source) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:423) at at.o2xfs.xfs.service.ReflectiveFactory.createResult(ReflectiveFactory.java:52) ... 4 more Caused by: java.lang.NullPointerException at at.o2xfs.xfs.win32.XfsWord.set(XfsWord.java:57) at at.o2xfs.xfs.v3_00.cdm.OutputPosition3.<init>(OutputPosition3.java:70) at at.o2xfs.xfs.v3_00.cdm.OutputPositions3.copy(OutputPositions3.java:45) at at.o2xfs.xfs.v3_00.cdm.OutputPositions3.get(OutputPositions3.java:52) at at.o2xfs.xfs.v3_00.cdm.CdmStatus3.getPositions(CdmStatus3.java:100) at at.o2xfs.xfs.v3_00.cdm.CdmStatus3.set(CdmStatus3.java:79) at at.o2xfs.xfs.v3_00.cdm.CdmStatus3.<init>(CdmStatus3.java:71) ... 8 more

VitalyEG commented 5 years ago

Could it be on incorrectle compiled hardware vendor libraries with options of freeing memory? Could you test, as example CdmStatusCommand with your example of service provider part, with cycle request of 20000 calls?

AndreasFagschlunger commented 5 years ago

Hi @VitalyEG Here ist what I did, changed the ShareFilesize in registry to 1048576 (1MB), skiped XfsServiceManager.getInstance().free:

} finally {
    if (wfsResult != null) {
        // XfsServiceManager.getInstance().free(wfsResult);
    }
}

I run into OutOfMemory with request ID 3535:

2019-04-28 22:23:43,285 DEBUG at.o2xfs.xfs.service.cmd.XfsCallable [MessageHandler][11] fireOperationCompleteEvent(WFSResult): wfsResult=at.o2xfs.xfs.WFSResult@1162b79[requestID=3535,service=1,timestamp=at.o2xfs.win32.SYSTEMTIME@14e6475[types=[2019, 4, 0, 28, 22, 23, 43, 285]],result=0,u=at.o2xfs.win32.Union@b6c813[size=4,fields={commandCode=301,eventID=301}],buffer=Address: 162BE136, Value: 162BE0D8]
2019-04-28 22:23:43,285 INFO at.o2xfs.xfs.service.cdm.CdmStatusCallable [main][1] call(): at.o2xfs.xfs.v3_00.cdm.CdmStatus3@18f5316[deviceState=ONLINE,safeDoor=CLOSED,dispenser=OK,intermediateStacker=EMPTY,positions={at.o2xfs.xfs.v3_00.cdm.OutputPosition3@9eb432[position=CENTER,shutter=CLOSED,positionStatus=EMPTY,transport=OK,transportStatus=EMPTY]},extra={key=value}]
...
WFMAllocateBuffer(ulSize=34, lpData=00000000): -42

With the free call enabled I did 50,000 status calls without problems:

2019-04-28 22:47:20,565 DEBUG at.o2xfs.xfs.service.cmd.XfsCallable [MessageHandler][11] fireOperationCompleteEvent(WFSResult): wfsResult=at.o2xfs.xfs.WFSResult@1e7ed18[requestID=50002,service=1,timestamp=at.o2xfs.win32.SYSTEMTIME@1e4206[types=[2019, 4, 0, 28, 22, 47, 20, 565]],result=0,u=at.o2xfs.win32.Union@d47278[size=4,fields={commandCode=301,eventID=301}],buffer=Address: 15FC5D36, Value: 15FC5C58]
2019-04-28 22:47:20,565 INFO at.o2xfs.xfs.service.cdm.CdmStatusCallable [main][1] call(): at.o2xfs.xfs.v3_00.cdm.CdmStatus3@12621ec[deviceState=ONLINE,safeDoor=CLOSED,dispenser=OK,intermediateStacker=EMPTY,positions={at.o2xfs.xfs.v3_00.cdm.OutputPosition3@1c09301[position=CENTER,shutter=CLOSED,positionStatus=EMPTY,transport=OK,transportStatus=EMPTY]},extra={key=value}]

The service provider calls WFMAllocateBuffer/WFMAllocateMore to allocate memory, where the application calls WFSFreeResult to free the memory allocated by the service provider. As long as this happens, the XFS Manager shouldn't run out of memory. I use the XFS Manager that comes with the XFS SDK:

ftp://ftp.cencenelec.eu/CEN/WhatWeDo/Fields/ICT/eBusiness/WS/XFS/CWA16926/SDK330.zip

The XFS Manager should be interchangeable, so you may try another XFS Manager. And it's still possible the service provider has it's own memory leak. But I can't find a problem within O²Xfs.

best regards, Andreas

VitalyEG commented 5 years ago

Hi Andreas! Sorry for so long time out. But we are still deciding this problem with service provider. So I don't close this issie.

VitalyEG commented 5 years ago

Hi Andreas! Great Thanks for the consultation. Really, Trouble was at the side of the service provider.