Service Virtualization

Expand all | Collapse all

Intermittent "Transaction Navigator No stateless match found"

  • 1.  Intermittent "Transaction Navigator No stateless match found"

    Broadcom Employee
    Posted Jan 31, 2019 04:31 PM

    I'm new to SV and ran into something that is testing my limits of SV troubleshooting.

    I've recorded two request-response pairs (the first for authentication, and the second to request data).

    When I deploy I am able query the simulation, however I am seeing it intermittently fail w/ a 404.

    Running the client (in this case a python script), it successfully processes 164 requests.

    On attempt 165 it fails... Sometimes it fails sooner, or later. It's weirdly random.

     

    ...

    01-31-19_15:34:55 start iteration 165
    01-31-19_15:34:55 0000 REQUEST URL: https://mysim.ca.com:8446/j_security_check
    01-31-19_15:34:55 0000 REQUEST HDR: Content-type = application/x-www-form-urlencoded
    01-31-19_15:34:55 0000 REQUEST BODY: j_username=darth&j_password=vader
    01-31-19_15:34:55 0000 sending request ...
    01-31-19_15:34:55 0000 AUTHENTICATION SUCCESS cookie:JSESSIONID=P6DDNP21i4EZ9Ia6cWN5a7hMleBp_93JWIy0WPag;91273224-26ef-3552-3a41-0931640446d3; path=/; secure; HttpOnly
    01-31-19_15:34:55 0000 BEGIN
    01-31-19_15:34:55 0001 REQUEST URL: https://mysim.ca.com:8446/dataservice/device
    01-31-19_15:34:55 0001 REQUEST HDR: Cookie = JSESSIONID=P6DDNP21i4EZ9Ia6cWN5a7hMleBp_93JWIy0WPag;91273224-26ef-3552-3a41-0931640446d3; path=/; secure; HttpOnly
    01-31-19_15:34:55 0001 sending request ...
    01-31-19_15:34:56 0001 HTTP ERROR <html>
    <head><title>404 Not Found</title></head>
    <body>
    <h1>Not Found</h1>
    <p>The requested URL was not found on this server.</p>
    <hr/>
    <p><i>The DevTest VSE service could not match your request to a recorded request.  Consider expanding your service image.</i></p>
    <br/><font size="-2">Produced by a DevTest virtualized web server.</font>
    </body>
    </html>

    HTTP Error 404: Not Found

     

    The vse_matches.log file shows...

     

    2019-01-31 20:37:45,450Z (15:37)[inventory_device [VS_inventory_device_Run]/1] INFO - Transaction Navigator No stateless match found
    2019-01-31 20:37:45,451Z (15:37)[inventory_device [VS_inventory_device_Run]/1] INFO - Response on the Wire HTTP/1.1 404 Not Found
    Server: LISA/Virtual-Environment-Server
    Date: Thu, 31 Jan 2019 15:37:44 EST
    X-Powered-By: LISA/10.4.0 (10.4.0.366)
    Content-Type: text/html
    Content-Length: 413

    <html>
    <head><title>404 Not Found</title></head>
    <body>
    <h1>Not Found</h1>
    <p>The requested URL was not found on this server.</p>
    <hr/>
    <p><i>The DevTest VSE service could not match your request to a recorded request.  Consider expanding your service image.</i></p>
    <br/><font size="-2">Produced by a DevTest virtualized web server.</font>
    </body>
    </html>

     

    It is not clear to me exactly what triggered the 404 considering the navigation and match styles are pretty simple.

    The log does suggest a response match problem, but nothing specific. I enabled DEBUG logging in the logging.properties files, but I don't see much more in the log that helps.

     

    Thoughts?

     

    Thank you,

    -Fred

    Attachment(s)



  • 2.  Re: Intermittent "Transaction Navigator No stateless match found"

    Posted Jan 31, 2019 05:38 PM

    For some reason, the incoming request is not matching anything in the VSI. Most common reason is that the operation and/or arguments are not matching transactions in the VSI. 

     

    Bear in mind that more or fewer arguments in a request than those in the VSI can cause issues. And, case sensitivity applies to each argument name. 

     

    Take a peak at the the "inbound request" that is dumped in the VS_inventory_device_Run.log just a few milliseconds prior to the 2019-01-31 20:37:45,450Z (15:37) timestamp you see in the vse.log? 

    Look for something similar to the following:

    Inbound Request {"id":0,"operation":"someOP","arguments":{"arg1":"val1","arg2":"val2"}, more stuff

    Compare this to the transactions in the VSI to see if anything is mismatching.

     

    If you don't see something useful in the VS_inventory_device_Run.log, you could add a bit of script to dump the incoming request into the VSE log.  To do this add an additional DPH in the VSM:

    1. Add a Scriptable DPH    Listen Step -> Filters -> VSE -> Data Protocol Filter -> Scriptable Data Protocol

    2. Add a few lines of script to print the contents of the incoming request into the vse.log file.

    %beanshell%

    _logger.info(" <<< >>> ")

    _logger.info("incoming request operation after DPHs is: {}", lisa_vse_request.getOperation() );

    _logger.info("incoming argument list after DPHs is: {}", lisa_vse_request.getArguments().toString() );

    Run the test until the error occurs and check the vse.log file. You might scan for "<<<" to help find the content faster.

    The arguments are printed as arg1=val1&arg2=val2 and so on.



  • 3.  Re: Intermittent "Transaction Navigator No stateless match found"

    Broadcom Employee
    Posted Feb 01, 2019 04:46 AM

    Before fiddling around with scripting you can also take a quick look at the Inspection View of the VSE Monitor in the Portal. The inspection view should show you the request's incoming operation and arguments for the transactions that did not match.



  • 4.  Re: Intermittent "Transaction Navigator No stateless match found"

    Broadcom Employee
    Posted Feb 01, 2019 10:31 AM

    It looks like the problem is related to the 2nd GET query and the failure to lookup with the session created on the previous [successful] login/authentication POST (using the generated JESSSIONID cookie / lisa.vse.sesion.key)>

    (I've attached VS_inventory_device_good|bad.log files with examples of both failure and success cases.)

     

    In most cases the GET /dataservice/device is working ...

     

     

    2019-02-01 14:38:50,446Z (09:38)[inventory_device [VS_inventory_device_Run]/1] INFO  - New session New session created for key: S7AGHN18e4GJ2IhAtXX9x1aGc1Ng_22WALf0MGrn&188062c6-b0e9-795b-f23e-1383963326ad

    ...

    2019-02-01 14:38:50,542Z (09:38)[inventory_device [VS_inventory_device_Run]/1] DEBUG - Inbound Request {"id":0,"operation":"GET /dataservice/device","arguments":{}}
    2019-02-01 14:38:50,542Z (09:38)[inventory_device [VS_inventory_device_Run]/1] INFO - Inbound Request {"id":0,"operation":"GET /dataservice/device/","arguments":{}}
    2019-02-01 14:38:50,542Z (09:38)[inventory_device [VS_inventory_device_Run]/1] INFO - Existing session Attached to existing session for key: S7AGHN18e4GJ2IhAtXX9x1aGc1Ng_22WALf0MGrn&188062c6-b0e9-795b-f23e-1383963326ad
    ...

     

    ... and [intermittently] it fails with ...

     

    2019-02-01 14:39:06,570Z (09:39)[inventory_device [VS_inventory_device_Run]/1] INFO  - New session New session created for key: V1NHTZ14ldJT1FsFeXF6l1fKw5Cz_39UVEp6CEca;170120a7-b302-3302-8035-7b79375ec167

    ...

    2019-02-01 14:39:06,657Z (09:39)[inventory_device [VS_inventory_device_Run]/1] DEBUG - Inbound Request {"id":0,"operation":"GET /dataservice/device","arguments":{}}
    2019-02-01 14:39:06,658Z (09:39)[inventory_device [VS_inventory_device_Run]/1] INFO - Inbound Request {"id":0,"operation":"GET /dataservice/device/","arguments":{}}
    2019-02-01 14:39:06,658Z (09:39)[inventory_device [VS_inventory_device_Run]/1] DEBUG - Operation match failure source: 'POST /j_security_check/', incoming: 'GET /dataservice/device/'
    2019-02-01 14:39:06,658Z (09:39)[inventory_device [VS_inventory_device_Run]/1] INFO - No Session ID No session identified
    2019-02-01 14:39:06,658Z (09:39)[inventory_device [VS_inventory_device_Run]/1] INFO - No Stateless Match Could not match a stateless transaction
    2019-02-01 14:39:06,659Z (09:39)[inventory_device [VS_inventory_device_Run]/1] WARN - No Match Request <?xml version="1.0" ?>


    <request operation="GET /dataservice/device/" matchTolerance="EXACT">
    <attributes>
    <parameter name="HTTP-Segment-Attr-0">dataservice</parameter>
    <parameter name="HTTP-Segment-Attr-1">device</parameter>
    </attributes>
    <metaData>
    <parameter name="HTTP-Method">GET</parameter>
    <parameter name="HTTP-URI">/dataservice/device</parameter>
    <parameter name="HTTP-Version">1.1</parameter>
    <parameter name="Accept-Encoding">identity</parameter>
    <parameter name="Host">servicesim.ca.com:8446</parameter>
    <parameter name="Cookie">JSESSIONID=V1NHTZ14ldJT1FsFeXF6l1fKw5Cz_39UVEp6CEca;170120a7-b302-3302-8035-7b79375ec167; path=/; secure; HttpOnly</parameter>
    <parameter name="Connection">close</parameter>
    <parameter name="User-Agent">Python-urllib/2.7</parameter>
    <parameter name="lisa.vse.session.key">V1NHTZ14ldJT1FsFeXF6l1fKw5Cz_39UVEp6CEca</parameter>
    <parameter name="lisa.vse.request.client.id">138.42.248.62:41856</parameter>
    <parameter name="matchedRule">GET /dataservice/device/</parameter>
    </metaData>
    </request>

     

    From the incoming GET request, I see the Cookie parameter and it seems to align with the generated key in the original POST.

     

    Still not clear why it works most of the time. Is there a subtle issue here or am I missing some additional configuration to relate the Cookie/JSESSION and lisa.vse.sesion.key?


    Thanks for the responses.

    -Fred



  • 5.  Re: Intermittent "Transaction Navigator No stateless match found"

    Posted Feb 01, 2019 11:56 AM

    This is an absolute guess.  But, I wonder if the issue is related to a semi-colon (;) that is embedded in the session key.

    The session key in the "good Log" looks like this and contains an ampersand:

    S7AGHN18e4GJ2IhAtXX9x1aGc1Ng_22WALf0MGrn&188062c6-b0e9....

    The session key in the "bad log" looks like this and contains a semi-colon.

    V1NHTZ14ldJT1FsFeXF6l1fKw5Cz_39UVEp6CEca;170120a7-b302....

    I am wondering if the semi-colon is causing DevTest to 'believe' that the end of the session key has been encountered; hence, not considering the GUID as part of the session key. 

     

    In the not found response, the Cookie response appears to me to 'believe' the cookie is shorter than it should be.

    <parameter name="Cookie">

    JSESSIONID=V1NHTZ14ldJT1FsFeXF6l1fKw5Cz_39UVEp6CEca;170120a7-b302-3302-8035-7b79375ec167;path=/; secure; HttpOnly</parameter>

     

    Maybe someone else can chime in here and let me know if this is off base.



  • 6.  Re: Intermittent "Transaction Navigator No stateless match found"

    Broadcom Employee
    Posted Feb 01, 2019 12:15 PM

    Ah... I think you are onto something. I ran my harness several more times and monitored the session ID.

    Each is failing when the SESSIONID has an embedded semi-colon:

     

    02-01-19_11:59:49 0001 request  HDR: Cookie = JSESSIONID=O5HDHG82z0VLEFgDyKL1p6tLeeDp_56TOQc4DVmo;39643141-f87b-7f70-cf47-3e39845590bf; path=/; secure; HttpOnly

    02-01-19_12:01:04 0001 request  HDR: Cookie = JSESSIONID=T8HVTX57hbWA4PdBfZA6f5bYtbIi_81NMGyFYNzk;34702748-2f45-4979-0731-5962631d304e; path=/; secure; HttpOnly

    02-01-19_12:01:32 0001 request  HDR: Cookie = JSESSIONID=B7MTOD21cdAH3An4dMU5s6fYc6Qq_08KDAw3MBgd;20051572-ec8d-145a-2950-4a319563545c; path=/; secure; HttpOnly

     

    JSESSIONIDs w/out a semi don't trigger the issue.

    ... 100's more ...

    02-01-19_12:04:52 0001 request HDR: Cookie = JSESSIONID=D5AQYB22ibMX0Yv1dIB7d8qGncMo_98MECwAJSag?05711071-d146-9d53-a309-32654120a4c8; path=/; secure; HttpOnly
    02-01-19_12:04:52 0001 request HDR: Cookie = JSESSIONID=C6SRWS33o9UC1GvFdNX0p4vOd0Ks_49QJNy3IQjxo44358067-2a97-3c0b-af73-6f909764f4e2; path=/; secure; HttpOnly
    02-01-19_12:04:53 0001 request HDR: Cookie = JSESSIONID=D5OCRR28daKX5IeEhCL8n8cGa1Md_31UEUp5DXaf"699e33a1-68ba-5266-b65e-15002002524c; path=/; secure; HttpOnly
    02-01-19_12:04:53 0001 request HDR: Cookie = JSESSIONID=W5UCIQ04o9UEBMd1kPS6x5cGt2Yg_65AVZg0DAqyY53334746-190b-1a4b-3313-08856091191c; path=/; secure; HttpOnly
    02-01-19_12:04:53 0001 request HDR: Cookie = JSESSIONID=L2EXKW43f5MO0Fq3hPK4u0jGodJl_40EKBdBHEwl;54066658-383b-290d-9c03-8c8960058525; path=/; secure; HttpOnly

     

    The VSE is generating these on behalf of the virtual server, yes? Is this something that I can configure?  

     

    -Fred



  • 7.  Re: Intermittent "Transaction Navigator No stateless match found"

    Posted Feb 01, 2019 01:21 PM

    I rarely use stateful services, but that's a great question. I don't know the specifics. However, you now have enough detail to raise a question with CA Support. My guess is that someone from engineering will need to answer the specifics. It could be that a bug has been identified.



  • 8.  Re: Intermittent "Transaction Navigator No stateless match found"

    Broadcom Employee
    Posted Feb 01, 2019 01:25 PM

    What does the Response look like where it has {{lisa.vse.sesion.key}} ?  Maybe we could script to replace/avoid " ; "   



  • 9.  Re: Intermittent "Transaction Navigator No stateless match found"

    Broadcom Employee
    Posted Feb 01, 2019 03:31 PM

    In the POST response Meta Data, Set-Cookie is assigned: "JSESSIONID={{lisa.vse.session.key}}; path=/; secure; HttpOnly". My client is receiving a JSESSION cookie with the embedded semicolon. I assume it originates from this POST response "template."

     

    When sending it back as part of the subsequent GET query I tried two things:

    1. removing the semicolon
    2. encoding it with %3B: 

     

    2019-02-01 20:11:02,814Z (15:11)[inventory_device [VS_inventory_device_Run]/1] INFO  - New session New session created for key: P1XRGI42t0AK0Qg8fMQ9y9mKs3Os_36XBYdCPJbn;94029015-de04-6410-2f47-3295112f01af

     

        <parameter name="Cookie">JSESSIONID%3DP1XRGI42t0AK0Qg8fMQ9y9mKs3Os_36XBYdCPJbn%3B94029015-de04-6410-2f47-3295112f01af%3B%20path%3D/%3B%20secure%3B%20HttpOnly</parameter>

     

    Neither of these made a difference.

    We need to add a --no-semicolons-in-cookie switch to VirtualServiceEnvironment.

    : )

     

    So, is this really a bug, or do I need to perform some magical encoding on the parameter value?

    Are semi-colons even a legal in the cookie? I didn't think they were.

    Thoughts?

     

    Regards,

    -Fred

     

    PS> From RFC 6265 - HTTP State Management Mechanism (not sure if this RFC is still authoritative. Looks current RFC 6265 - HTTP State Management Mechanism )

     

    set-cookie-header = "Set-Cookie:" SP set-cookie-string
    set-cookie-string = cookie-pair *( ";" SP cookie-av )
    cookie-pair = cookie-name "=" cookie-value
    cookie-name = token
    cookie-value = *cookie-octet / ( DQUOTE *cookie-octet DQUOTE )
    cookie-octet = %x21 / %x23-2B / %x2D-3A / %x3C-5B / %x5D-7E
    ; US-ASCII characters excluding CTLs,
    ; whitespace DQUOTE, comma, semicolon,
    ; and backslash



  • 10.  Re: Intermittent "Transaction Navigator No stateless match found"
    Best Answer

    Broadcom Employee
    Posted Feb 01, 2019 06:43 PM

    The issue is the pattern used to generate the token. Open the VSI in the workstation. Go to the start of the conversation and click the person icon. This will show the token pattern. Click the ? icon to see the possible Pattern symbols. The Token Pattern in the VSI contained a . - (dot) anything printable. That allowed a semicolon. Changing that to an underscore solved the issue.



  • 11.  Re: Intermittent "Transaction Navigator No stateless match found"

    Broadcom Employee
    Posted Feb 04, 2019 09:05 AM

    Thanks Karl! That was it. The "template" '.' specifier randomized a printable character and explains the randomness of the failure.



  • 12.  Re: Intermittent "Transaction Navigator No stateless match found"

    Broadcom Employee