"Error Tidying. Could not tidy ... out of the way, by adding .BAD" when using Q2.deployElement()?

81 views Asked by At

I am attempting to create 10_channel.xml and 20_mux.xml Beans dynamically, while Q2 is running already.

The user will provide info via JSON post request like below:

    "config": {
        "keyset": "KEYSET_1",
        "pinblockFmt": "01 - ISO 0 Format",
        "acq": {
            "format": "VISANET",
            "portNumber": 9405
        },
        "iss": {
            "format": "ISO4",
            "portNumber": 9488
        }
    }

The code will take the above info, and use JDOM2 to create the xml files and place them in Q2 deploy folder

    private void createJposChannel(Map<String, Object> client, String portName) {
        String isoChannel;
        String ip;

        if (client.get("format").toString().equalsIgnoreCase("VISANET")) {
            isoChannel = "org.jpos.iso.channel.VAPChannel";
        } else {
            isoChannel = "org.jpos.iso.channel.CSChannel";
        }

        if (client.containsKey("ip")) {
            ip = (String) client.get("ip");
        } else {
            ip = "10.x.x.x";
        }


        try {
            Element channelAdaptor = new Element("channel-adaptor");
            channelAdaptor.setAttribute("name", portName + "-channel");
            channelAdaptor.setAttribute("class", "org.jpos.q2.iso.ChannelAdaptor");
            channelAdaptor.setAttribute("logger", "Q2");

            Element channel = new Element("channel");
            channel.setAttribute("class", isoChannel);
            channel.setAttribute("packager", "org.jpos.iso.packager.GenericPackager");
            channel.setAttribute("logger", "Q2");

            Element property0 = new Element("property");
            property0.setAttribute("name", "packager-config");
            property0.setAttribute("value", "src/main/resources/" +
                    client.get("format").toString().toLowerCase() + ".xml");

            Element property1 = new Element("property");
            property1.setAttribute("name", "host");
            property1.setAttribute("value", ip);

            Element property2 = new Element("property");
            property2.setAttribute("name", "port");
            property2.setAttribute("value", portName.split("-")[0]); //remove system #

            Element property3 = new Element("property");
            property3.setAttribute("name", "timeout");
            property3.setAttribute("value", "3600000"); //default timeout time

            channel.addContent(property0);
            channel.addContent(property1);
            channel.addContent(property2);
            channel.addContent(property3);

            Element in = new Element("in");
            in.setText(portName + "-channel-send");

            Element out = new Element("out");
            out.setText(portName + "-channel-receive");

            Element reconnect = new Element("reconnect-delay");
            reconnect.setText("10000");

            channelAdaptor.addContent(channel);
            channelAdaptor.addContent(in);
            channelAdaptor.addContent(out);
            channelAdaptor.addContent(reconnect);

            IsotesttoolApplication.q2.deployElement(channelAdaptor, String.format("10_%s_channel.xml", portName), false, true);
            Thread.sleep(2000);

            /*XMLOutputter xmlOutput = new XMLOutputter();
            xmlOutput.setFormat(Format.getPrettyFormat());
            xmlOutput.output(channelAdaptor, System.out);*/

        } catch (IOException e) {
            e.printStackTrace();
        } catch (ISOException e) {
            throw new RuntimeException(e);
        } catch (GeneralSecurityException e) {
            throw new RuntimeException(e);
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        }
    }

There is very similar code creating the mux files as well. Will omit to keep post shorter.

However, I am getting the below error only for the acq channel, 10_9405-01_channel.xml. The muxes, and even the channel for port 9488, do not get any errors:

        <log realm="Q2.system" at="2023-10-20T12:09:52.198">
  <info>
    created deploy/10_9405-01_channel.xml
  </info>
</log>
<log realm="Q2.system" at="2023-10-20T12:09:52.203">
  <warn>
    Error Tidying. Could not tidy  C:\Users\username\ISOTOPE\src\main\java\deploy\10_9405-01_channel.xml out of the way, by adding .BAD
    It could not be called: C:\Users\username\ISOTOPE\src\main\java\deploy\10_9405-01_channel.xml.BAD see log above for detail of problem.
  </warn>
</log>
<log realm="Q2.system" at="2023-10-20T12:09:52.203" lifespan="3ms">
  <info>
    <exception name="Error on line 1 of document file:/C:/Users/username/ISOTOPE/src/main/java/deploy/10_9405-01_channel.xml: Premature end of file.">
    org.jdom2.input.JDOMParseException: Error on line 1 of document file:/C:/Users/username/ISOTOPE/src/main/java/deploy/10_9405-01_channel.xml: Premature end of file.
    at org.jdom2.input.sax.SAXBuilderEngine.build(SAXBuilderEngine.java:230)
    at org.jdom2.input.sax.SAXBuilderEngine.build(SAXBuilderEngine.java:277)
    at org.jdom2.input.sax.SAXBuilderEngine.build(SAXBuilderEngine.java:264)
    at org.jdom2.input.SAXBuilder.build(SAXBuilder.java:1104)
    at org.jpos.q2.Q2.deploy(Q2.java:563)
    at org.jpos.q2.Q2.deploy(Q2.java:392)
    at org.jpos.q2.Q2.run(Q2.java:258)
    at java.lang.Thread.run(Thread.java:750)
Caused by: org.xml.sax.SAXParseException; systemId: file:/C:/Users/username/ISOTOPE/src/main/java/deploy/10_9405-01_channel.xml; lineNumber: 1; columnNumber: 1; Premature end of file.
    at com.sun.org.apache.xerces.internal.util.ErrorHandlerWrapper.createSAXParseException(ErrorHandlerWrapper.java:204)
    at com.sun.org.apache.xerces.internal.util.ErrorHandlerWrapper.fatalError(ErrorHandlerWrapper.java:178)
    at com.sun.org.apache.xerces.internal.impl.XMLErrorReporter.reportError(XMLErrorReporter.java:400)
    at com.sun.org.apache.xerces.internal.impl.XMLErrorReporter.reportError(XMLErrorReporter.java:327)
    at com.sun.org.apache.xerces.internal.impl.XMLScanner.reportFatalError(XMLScanner.java:1467)
    at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl$PrologDriver.next(XMLDocumentScannerImpl.java:1042)
    at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.next(XMLDocumentScannerImpl.java:605)
    at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.next(XMLNSDocumentScannerImpl.java:113)
    at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanDocument(XMLDocumentFragmentScannerImpl.java:507)
    at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:867)
    at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:796)
    at com.sun.org.apache.xerces.internal.parsers.XMLParser.parse(XMLParser.java:142)
    at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(AbstractSAXParser.java:1216)
    at com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl$JAXPSAXParser.parse(SAXParserImpl.java:644)
    at org.jdom2.input.sax.SAXBuilderEngine.build(SAXBuilderEngine.java:217)
    ... 7 more
    </exception>
  </info>
</log>
<log realm="Q2.system" at="2023-10-20T12:09:52.204">
  <info>
    modified deploy/10_9405-01_channel.xml
  </info>
</log>
<log realm="Q2.system" at="2023-10-20T12:09:52.211" lifespan="6ms">
  <info>
    deploy: C:\Users\username\ISOTOPE\src\main\java\deploy\10_9405-01_channel.xml
  </info>
</log>
<log realm="channel/10.x.x.x:9405" at="2023-10-20T12:09:52.328" lifespan="81ms">
  <connect>
    Try 0 10.x.x.x:9405
      Connection established to 10.x.x.x:9405
  </connect>
</log>
<channel-adaptor name="9405-01-channel" class="org.jpos.q2.iso.ChannelAdaptor" logger="Q2">
  <channel class="org.jpos.iso.channel.VAPChannel" packager="org.jpos.iso.packager.GenericPackager" logger="Q2">
    <property name="packager-config" value="src/main/resources/visanet.xml" />
    <property name="host" value="10.x.x.x" />
    <property name="port" value="9405" />
    <property name="timeout" value="3600000" />
  </channel>
  <in>9405-01-channel-send</in>
  <out>9405-01-channel-receive</out>
  <reconnect-delay>10000</reconnect-delay>
</channel-adaptor><log realm="Q2.system" at="2023-10-20T12:09:54.220">
  <info>
    created deploy/20_9405-01_mux.xml
  </info>
</log>
<log realm="Q2.system" at="2023-10-20T12:09:54.238" lifespan="16ms">
  <info>
    deploy: C:\Users\username\ISOTOPE\src\main\java\deploy\20_9405-01_mux.xml
  </info>
</log>
<log realm="Q2.system" at="2023-10-20T12:09:54.238">
  <info>
    modified deploy/20_9405-01_mux.xml
  </info>
</log>
<mux class="org.jpos.q2.iso.QMUX" logger="Q2" name="9405-01-mux" realm="9405-01-realm">
  <in>9405-01-channel-receive</in>
  <out>9405-01-channel-send</out>
  <ready>9405-01-channel.ready</ready>
  <request-listener class="com.visa.ip.isotesttool.service.EchoResponder" />
  <request-listener class="com.visa.ip.isotesttool.service.AutoResponder" />
</mux><log realm="Q2.system" at="2023-10-20T12:09:56.239">
  <info>
    created deploy/10_9488-01_channel.xml
  </info>
</log>
<log realm="Q2.system" at="2023-10-20T12:09:56.242" lifespan="3ms">
  <info>
    deploy: C:\Users\username\ISOTOPE\src\main\java\deploy\10_9488-01_channel.xml
  </info>
</log>
<log realm="Q2.system" at="2023-10-20T12:09:56.257">
  <info>
    modified deploy/10_9488-01_channel.xml
  </info>
</log>
<log realm="channel/10.x.x.x:9488" at="2023-10-20T12:09:56.343" lifespan="86ms">
  <connect>
    Try 0 10.x.x.x:9488
      Connection established to 10.x.x.x:9488
  </connect>
</log>
<channel-adaptor name="9488-01-channel" class="org.jpos.q2.iso.ChannelAdaptor" logger="Q2">
  <channel class="org.jpos.iso.channel.CSChannel" packager="org.jpos.iso.packager.GenericPackager" logger="Q2">
    <property name="packager-config" value="src/main/resources/iso4.xml" />
    <property name="host" value="10.x.x.x" />
    <property name="port" value="9488" />
    <property name="timeout" value="3600000" />
  </channel>
  <in>9488-01-channel-send</in>
  <out>9488-01-channel-receive</out>
  <reconnect-delay>10000</reconnect-delay>
</channel-adaptor><log realm="Q2.system" at="2023-10-20T12:09:58.245">
  <info>
    created deploy/20_9488-01_mux.xml
  </info>
</log>
<log realm="Q2.system" at="2023-10-20T12:09:58.251" lifespan="3ms">
  <info>
    deploy: C:\Users\username\ISOTOPE\src\main\java\deploy\20_9488-01_mux.xml
  </info>
</log>
<log realm="Q2.system" at="2023-10-20T12:09:58.252">
  <info>
    modified deploy/20_9488-01_mux.xml
  </info>
</log>

Also, as you can see from the logs, it looks like the 10_9405-01_channel and mux are both deploying anyways, after the error. My program is able to run fine despite that error, and I can see the transaction flow like I expect to.

So why is it complaining about "Error Tidying" and why is it only for one channel xml, and not the other?

Edit: Here is the generated deploy file that is failing

<?xml version="1.0" encoding="UTF-8"?>
<channel-adaptor name="9405-01-channel" class="org.jpos.q2.iso.ChannelAdaptor" logger="Q2" instance="208ac0a3-2b7e-4282-aab4-301d4f0859c3">
  <channel class="org.jpos.iso.channel.VAPChannel" packager="org.jpos.iso.packager.GenericPackager" logger="Q2">
    <property name="packager-config" value="src/main/resources/visanet.xml" />
    <property name="host" value="10.x.x.x" />
    <property name="port" value="9405" />
    <property name="timeout" value="3600000" />
  </channel>
  <in>9405-01-channel-send</in>
  <out>9405-01-channel-receive</out>
  <reconnect-delay>10000</reconnect-delay>
</channel-adaptor>

versus the same code generated for the issuer port, which is not failing:

<?xml version="1.0" encoding="UTF-8"?>
<channel-adaptor name="9488-01-channel" class="org.jpos.q2.iso.ChannelAdaptor" logger="Q2" instance="208ac0a3-2b7e-4282-aab4-301d4f0859c3">
  <channel class="org.jpos.iso.channel.CSChannel" packager="org.jpos.iso.packager.GenericPackager" logger="Q2">
    <property name="packager-config" value="src/main/resources/iso4.xml" />
    <property name="host" value="10.x.x.x" />
    <property name="port" value="9488" />
    <property name="timeout" value="3600000" />
  </channel>
  <in>9488-01-channel-send</in>
  <out>9488-01-channel-receive</out>
  <reconnect-delay>10000</reconnect-delay>
</channel-adaptor>
1

There are 1 answers

8
Andrés Alcarraz On BEST ANSWER

Judging for the message:

file:/C:/Users/username/ISOTOPE/src/main/java/deploy/10_9405-01_channel.xml: > Premature end of file.

And the fact that it works for other channels, I would say it's most probably due to Q2 starting to read the file before it is completely written.

You should write the files to another temp folder and then perform a move operation, so that, when Q2 sees the file, it is already completely written.

Even if you didn't have this problem, that is a good practice, because if it doesn't happen frequently, it could happen sometime. That code would be in the IsotesttoolApplication.q2.deployElement( method.

EDIT: I see the deployElement method is from the Q2 class, perhaps that method you do what I said, in that case, you could create an issue in the jPOS's GitHub.

Meanwhile, a workaround would be to write your version of the method that writes to another place and then perform the move.

EDIT 2: If the error consistently happens in the same way. It may be because Q2 starts reading the second file, just after it was created. The error is consistent with having an empty XML file in the deploy directory:

touch deploy/test.xml

Will produce this:

    <exception name="Error on line 1 of document file:/media/disk/Documents/cabal-uy/migracion/jpos-externo/build/install/facade-externo/deploy/test.xml: Premature end of file.">
    org.jdom2.input.JDOMParseException: Error on line 1 of document file:/media/disk/Documents/cabal-uy/migracion/jpos-externo/build/install/facade-externo/deploy/test.xml: Premature end of file.
    at org.jdom2.input.sax.SAXBuilderEngine.build(SAXBuilderEngine.java:230)
    at org.jdom2.input.sax.SAXBuilderEngine.build(SAXBuilderEngine.java:277)
    at org.jdom2.input.sax.SAXBuilderEngine.build(SAXBuilderEngine.java:264)
    at org.jdom2.input.SAXBuilder.build(SAXBuilder.java:1104)
    at org.jpos.q2.Q2.deploy(Q2.java:563)
    at org.jpos.q2.Q2.deploy(Q2.java:392)
    at org.jpos.q2.Q2.run(Q2.java:258)
    at java.base/java.lang.Thread.run(Thread.java:833)

Which is the same as yours.

So, I would try to add some time between the calls to Q2.deploy. Or, on the contrary, if you are processing them in different places, you could also check if creating the elements first, and then deploy them all at once could also work, but there is no warranty.

The best approach would be to try to fix that in jPOS, but for that you should provide a minimal reproducible example and create the issue.