Received message coudn't be accepted

[timonych]

Hello @tilln !

At first, Great thanks for making such tool for jMeter.

After I have tried - jMeter has successfull sent ISO8583 to My Web-Service. But when WS has sent responce - jMeter coudn't accept it and set timeout.

Have checked it via WireShark.

Is any ideas why it happens?

[tilln]

Hi @timonych

I would need a bit more information.

If you have seen the response message in Wireshark then it's most likely a configuration problem of some sort. For example, if there is a mismatch between the response message and the packager config file, the sampler would not be able to unpack the response, which would result in a timeout and error message being logged.

Have you checked the JMeter log file for errors and can you post the error message here? If there are no errors, I would suggest running again with debug logging (e.g. jmeter -LDEBUG=nz.co.breakpoint.jmeter.iso8583) and providing the relevant parts here.

[timonych]

I have checked packager config file and doesn't seen any problem with matching, e.g. isofield length, type.

Also, I have tryed to run jMeter and doesn't seen before. In TROUBLESHOOTING there is jmeter -Lnz.co.breakpoint.iso8583=DEBUG - with this parameter

2019-08-21 12:15:41,089 INFO o.a.j.JMeter: LogLevel: nz=.co.breakpoint.iso8583=DEBUG
2019-08-21 12:15:41,089 WARN o.a.j.JMeter: Invalid log level, '.co.breakpoint.iso8583=DEBUG' for 'nz'.

jmeter-1.log

with jmeter -LDEBUG=nz.co.breakpoint.jmeter.iso8583

2019-08-21 12:17:35,876 WARN o.a.j.JMeter: Invalid log level, 'nz' for 'DEBUG'.
2019-08-21 12:17:35,877 ERROR o.a.j.JMeter: An error occurred: 
java.lang.IllegalArgumentException: Unknown arg: .co.breakpoint.jmeter.iso8583

jmeter-2.log

[tilln]

Sorry, it's supposed to be -Lnz.co.breakpoint.iso8583=DEBUG Can you please give it another try?

[timonych]

Sorry, it's supposed to be -Lnz.co.breakpoint.iso8583=DEBUG Can you please give it another try?

No success :(

jmeter.log

[tilln]

Are you sure your command line is correct?

2019-08-21 15:10:12,362 INFO o.a.j.JMeter: LogLevel: nz=.co.breakpoint.iso8583=DEBUG
2019-08-21 15:10:12,362 WARN o.a.j.JMeter: Invalid log level, '.co.breakpoint.iso8583=DEBUG' for 'nz'.

[timonych]

Maybe this error has appeared after trying to start jMeter via PowerShell.

Start via CMD and there is no such message, but no any additional info.

jmeter.log

[tilln]

Because the class name in the README is incorrect. It should be -Lnz.co.breakpoint.jmeter.iso8583=DEBUG (whoops).

[timonych]

-Lnz.co.breakpoint.jmeter.iso8583=DEBUG (whoops).

This works! But I don't have success but now I can analyze logs. If any question will ask about it after.

Big thanks!

[timonych]

I have tryed to understood what is going on and have found that QBeans has sent and received message

2019-08-23 10:19:29,067 DEBUG n.c.b.j.i.Q2: (channel/10.1.59.53:4445) [send] Out: 0360 884646 151685  
2019-08-23 10:19:29,860 DEBUG n.c.b.j.i.Q2: (channel/10.1.59.53:4445) [receive]  In: 0370 884646 1117    

But after Sampler, as I think, couldn't recognize the responce.

jmeter.log ws-log.txt

[tilln]

I think the reason for this timeout is the way jPOS matches request and response messages:

It calculates a key for the outgoing request and only when an incoming message with a matching key is received, it is returned as a response, otherwise a timeout occurs. This key is normally calculated based on the message fields 0 (MTI), 11 and 41 (see QMUX.getKey)

It is possible to configure the QMUX to use different fields than the default, but this plugin does not currently support this sort of configuration, though I'm happy to include this in the next release.

From your JMeter/Q2 log you can see that the response key does not in fact match as field 41 is different:

Out: 0360 884646 151685  
In: 0370 884646 1117    

Your ws-log.txt confirms that

23/08/2019 10:19:30.357 [pool-3-thread-1] DEBUG r.b.s.FrontEndConnection - Sent message:
Type: 370
...
11: 884646
...
41: 1117

What looks suspicious is that field 41 of the server-side received message is interpreted as byte[]

41: [B@d0cd9b5

But I can't see how the bytes 31 35 31 36 38 35 20 20 would end up as 1117.

Perhaps you can confirm whether field 41 is supposed to be echoed in the server response? Otherwise you could possibly use field 37 (RETRIEVAL REFERENCE NUMBER).

[timonych]

In Europay protocol 41 Field is terminal ID and WS has a static ID

#Merchant ID used when impersonating as device during ISO8583 conversation
terminal.merchantId=7777

#Terminal ID used when impersonating as device during ISO8583 conversation
terminal.terminalId=1117

I have tryed to send 1117 as terminal ID in iso 8583, but no success.

I will wait for next release where is will be possible to configure QMUX to use another field for matching.

Great thanks for Your explanation and pushing this module!

[tilln]

@timonych Here is a snapshot release for you to try out. See updated README or QMUX documentation. Please let me know if this works for you.

[timonych]

@tilln

No success. :(

2019-08-23 16:22:40,678 INFO o.a.j.e.StandardJMeterEngine: Running the test!
2019-08-23 16:22:40,678 INFO o.a.j.s.SampleEvent: List of sample_variables: []
2019-08-23 16:22:40,679 DEBUG n.c.b.j.i.ISO8583Config: Creating Q2
2019-08-23 16:22:40,682 INFO n.c.b.j.i.Q2: (Q2.system) Q2 started, deployDir=D:\jMeter\deploy, environment=default
2019-08-23 16:22:40,686 DEBUG n.c.b.j.i.Q2: (Q2.system) [version] jPOS 2.1.3 master/95b8dce (2019-06-16 15:16:57 ART) 

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

jPOS Community Edition, licensed under GNU AGPL v3.0.
This software is probably not suitable for commercial use.
Please see http://jpos.org/license for details.

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Darwin)

iQEcBAEBAgAGBQJMolHDAAoJEOQyeO71nYtFv74H/3OgehDGEy1VXp2U3/GcAobg
HH2eZjPUz53r38ARPiU3pzm9LwDa3WZgJJaa/b9VrJwKvbPwe9+0kY3gScDE1skT
ladHt+KHHmGQArEutkzHlpZa73RbroFEIa1qmN6MaDEHGoxZqDh0Sv2cpvOaVYGO
St8ZaddLBPC17bSjAPWo9sWbvL7FgPFOHhnPmbeux8SLtnfWxXWsgo5hLBanKmO1
1z+I/w/6DL6ZYZU6bAJUk+eyVVImJqw0x3IEElI07Nh9MC6BA4iJ77ejobj8HI2r
q9ulRPEqH9NR79619lNKVUkE206dVlXo7xHmJS1QZy5v/GT66xBxyDVfTduPFXk=
=oP+v
-----END PGP SIGNATURE-----

2019-08-23 16:22:40,688 DEBUG n.c.b.j.i.ISO8583Config: 'ISO8583 Config' setting up QBeans jmeter-01633003
2019-08-23 16:22:40,689 DEBUG n.c.b.j.i.ISO8583Config: Deploying <channel-adaptor name="jmeter-01633003-channel" logger="Q2"><in>jmeter-01633003-send</in><out>jmeter-01633003-receive</out><reconnect-delay>10000</reconnect-delay><wait-for-workers-on-stop>yes</wait-for-workers-on-stop><channel name="jmeter-01633003" class="org.jpos.iso.channel.ASCIIChannel" packager="org.jpos.iso.packager.GenericPackager" header="" logger="Q2"><property name="packager-config" value="D:/jMeter/Development/europay-iBank.xml" /><property name="host" value="vmupsell-test" /><property name="port" value="4445" /></channel></channel-adaptor>
2019-08-23 16:22:40,693 DEBUG n.c.b.j.i.ISO8583Config: Deploying <qmux name="jmeter-01633003-mux" logger="Q2"><in>jmeter-01633003-receive</in><out>jmeter-01633003-send</out><unhandled>jmeter-01633003-unhandled</unhandled><ready>jmeter-01633003.ready</ready><key mti="0370">11</key></qmux>
2019-08-23 16:22:40,695 INFO o.a.j.g.u.JMeterMenuBar: setRunning(true, *local*)
2019-08-23 16:22:40,696 DEBUG n.c.b.j.i.Q2: (channel/10.1.59.53:4445) [connect] Try 0 vmupsell-test:4445
2019-08-23 16:22:40,705 INFO o.a.j.e.StandardJMeterEngine: Starting ThreadGroup: 1 : Thread Group
2019-08-23 16:22:40,705 INFO o.a.j.e.StandardJMeterEngine: Starting 1 threads for group Thread Group.
2019-08-23 16:22:40,705 INFO o.a.j.e.StandardJMeterEngine: Thread will continue on error
2019-08-23 16:22:40,705 INFO o.a.j.t.ThreadGroup: Starting thread group... number=1 threads=1 ramp-up=1 delayedStart=false
2019-08-23 16:22:40,706 INFO o.a.j.t.ThreadGroup: Started thread group number 1
2019-08-23 16:22:40,706 INFO o.a.j.e.StandardJMeterEngine: All thread groups have been started
2019-08-23 16:22:40,708 INFO o.a.j.t.JMeterThread: Thread started: Thread Group 1-1
2019-08-23 16:22:40,709 DEBUG n.c.b.j.i.ISO8583Sampler: Applying config 'ISO8583 Config'
2019-08-23 16:22:40,709 DEBUG n.c.b.j.i.ISO8583Config: Creating packager from 'D:/jMeter/Development/europay-iBank.xml'
2019-08-23 16:22:40,713 DEBUG n.c.b.j.i.ISO8583Sampler: sampleStart
2019-08-23 16:22:40,714 DEBUG n.c.b.j.i.Q2: (channel/10.1.59.53:4445) [send] Out: 0360 884646 1117    
2019-08-23 16:22:41,069 DEBUG n.c.b.j.i.Q2: (channel/10.1.59.53:4445) [receive]  In: 0370 884646 1117    
2019-08-23 16:23:00,714 DEBUG n.c.b.j.i.ISO8583Sampler: sampleEnd
2019-08-23 16:23:00,714 DEBUG n.c.b.j.i.ISO8583Sampler: Packed request '30333630e234040028e10000000000200000000031363132333435373839313233343536373839373030303030383137323335303032383834363436313930383137323335303032323131303030303337313233343537383931323334353637383d32313130323031303030303030303030303030303430393331333838343634363131313720202020416c6661204973732020202020202033392055474c494348534b41594120533e5941524f534c41564c20202020202020202020203e5255303236343930323338353130364131423243333835303641314232433338'
2019-08-23 16:23:00,715 INFO o.a.j.t.JMeterThread: Thread is done: Thread Group 1-1
2019-08-23 16:23:00,715 INFO o.a.j.t.JMeterThread: Thread finished: Thread Group 1-1
2019-08-23 16:23:00,715 INFO o.a.j.e.StandardJMeterEngine: Notifying test listeners of end of test
2019-08-23 16:23:00,715 DEBUG n.c.b.j.i.ISO8583Config: Shutting down QBeans
2019-08-23 16:23:00,715 DEBUG n.c.b.j.i.ISO8583Config: Undeploying jmeter-01633003-mux
2019-08-23 16:23:00,716 DEBUG n.c.b.j.i.ISO8583Config: Undeploying jmeter-01633003-channel
2019-08-23 16:23:00,717 INFO n.c.b.j.i.Q2: (Q2.system) shutting down
2019-08-23 16:23:00,717 INFO n.c.b.j.i.Q2: (Q2.system) shutdown done
2019-08-23 16:23:00,718 INFO o.a.j.g.u.JMeterMenuBar: setRunning(false, *local*)

[tilln]

Try setting the MTI Mapping to 0123456789 0123456789 0022446689 so that the 7 in 0370 gets mapped to a 6 so it matches the 0360.

[timonych]

@tilln

Increadible! It now works! Great thanks for helping!

I have tryed to use default mti mapping and nothing. 0123456789 0123456789 0022446689 - Your version 0123456789 0123456789 0022446789 - default

The differences is that 6 and 7 in last block. How can I calculate by myself this value?

Also, Do you have any wallet for donations?

[tilln]

Glad it's working for you now.

There's nothing really to calculate. Those strings are just lookup maps, and the input digit is used as the index position.

For example, with 0022446689, your 037x response is mapped to a 036x request like this:

MTI In	0	0	2	2	4	4	6	6	8	9	MTI Out
030x	0										030x
031x		0									030x
032x			2								032x
033x				2							032x
034x					4						034x
035x						4					034x
036x							6				036x
037x								6			036x
038x									8		038x
039x										9	039x

The best donation you can make is to contribute by testing and making open source better :-)

[timonych]

@tilln

Also, there old version of Readme on Main Page. :(

[tilln]

Because the main page shows the master branch, and this fix hadn't been merged yet.

[tilln]

@Rahulkhotre Can you please open a separate issue and provide logs?

Though it may be as simple as configuring key fields in the Mux Key Configuration, since your message does not contain field 41 which is a default mapping field.

So, you may want to try adding an entry with "Key Fields" 11 and perhaps 7 or another field that has a unique value for each handshake:	MTI	Key Fields
2804	7 11

Also, the "Response Code Field" and "Success Response Code" are most likely wrong as it looks like you put the response MTI in there. Instead, I suggest you leave the defaults 39 and 00 in there.

[Rahulkhotre]

@tilln , I have raised the separate issue as below.

https://github.com/tilln/jmeter-iso8583/issues/69

Please provide your input.