Issue Creating Replayer JSON File with Logshark 4.1.2

Paramesh40 commented 4 years ago

Hi Everyone,

I've been using Logshark from quiet time now and when tried to use for Replay running into an issue where Replayer JSON file is not being created and the moment I run the command with Replayer Plugin, it throws uncaught exception in command prompt and a windows Logshark task/menu pops up with message that says Logshark has stopped working and force me to close the program.

I've even excluded Replayer from "PluginsToExcludeFromDefaultSet": "" so that Replayer is enabled before running but no luck.

Looking the error message it highlights the same part i.e. Unable to Launch Replayer.

Command Prompt Error:

D:\LogShark>LogShark.exe "D:\Logs\abc.zip" --plugins ReplayCreation info: LogShark.LogSharkRunner[0] Starting to process Log set D:\Logs\abc.zip info: LogShark.LogSharkRunner[0] Generated Run ID: 20071512391699-servername-abc info: LogShark.LogSharkRunner[0] Hyper Writer requested. Initializing writer factory... info: LogShark.LogSharkRunner[0] Using temp folder D:\TEMP\2\LogShark info: LogShark.LogParser.TableauLogsExtractor[0] Starting TableauLogsExtractor for log set D:\Logs\abc.zip info: LogShark.LogParser.TableauLogsExtractor[0] Provided log set appears to be zip file info: LogShark.LogParser.TableauLogsExtractor[0] Looking for known nested zip files inside zip file 'D:\Logs\abc.zip ' info: LogShark.LogParser.TableauLogsExtractor[0] No known nested zip files found in 'D:\Logs\abc.zip info: LogShark.LogParser.TableauLogsExtractor[0] Completed TableauLogsExtractor for log set D:\Logs\abc.zip info: LogShark.Plugins.PluginInitializer[0] Starting to load plugins for string: ReplayCreation info: LogShark.LogParser.TableauLogsExtractor[0] Disposing log extractor temporary files... info: LogShark.LogParser.TableauLogsExtractor[0] Log extractor temporary files disposed

at LogShark.Plugins.PluginInitializer.GetPlugins(Boolean defaultPluginsWereRe quested, ICollection1 explicitlyRequestedPlugins, ICollection1 defaultSet, ICo llection1 excludedPlugins, Boolean usePluginsFromLogSharkAssembly) --- End of inner exception stack trace --- at LogShark.Plugins.PluginInitializer.GetPlugins(Boolean defaultPluginsWereRe quested, ICollection1 explicitlyRequestedPlugins, ICollection1 defaultSet, ICo llection1 excludedPlugins, Boolean usePluginsFromLogSharkAssembly) at LogShark.Plugins.PluginInitializer..ctor(IWriterFactory writerFactory, Log SharkConfiguration config, IProcessingNotificationsCollector processingNotificat ionsCollector, ILoggerFactory loggerFactory, Boolean usePluginsFromLogSharkAssem bly) at LogShark.LogSharkRunner.ReadLogsAndGenerateDataSets(IWriterFactory writerF actory) at LogShark.LogSharkRunner.ProcessLog() at LogShark.LogSharkRunner.Run() at LogShark.Program.OnExecute() at McMaster.Extensions.CommandLineUtils.Conventions.ExecuteMethodConvention.I nvokeAsync(MethodInfo method, Object instance, Object[] arguments) at McMaster.Extensions.CommandLineUtils.Conventions.ExecuteMethodConvention.O nExecute(ConventionContext context) at McMaster.Extensions.CommandLineUtils.Conventions.ExecuteMethodConvention.<

Looking at hyperd.logs I could see an error message saying communication failure : No process is on the other end of the pipe.

{"ts":"2020-07-15T22:17:41.306","pid":5492,"tid":"1a64","sev":"info","req":"-","sess":"-","k":"watchdog-started","v":{"probing-frequency":60,"timeout":300,"max-consecutive-hangs":5,"action":"terminate"}} {"ts":"2020-07-15T22:17:41.353","pid":5492,"tid":"a70","sev":"error","req":"-","sess":"-","k":"connection-communication-failure","v":{"exception":{"type":"system_error","message":"No process is on the other end of the pipe","error-code":233,"error-category":"system","error-message":"No process is on the other end of the pipe"},"source":"CallbackConnectionCheck"}} {"ts":"2020-07-15T22:17:41.353","pid":5492,"tid":"a70","sev":"info","req":"-","sess":"-","k":"monitor-endpoint-initiate-shutdown","v":{}} {"ts":"2020-07-15T22:17:41.353","pid":5492,"tid":"1498","sev":"fatal","req":"-","sess":"-","k":"server-shutdown-signal","v":{"start-time-delta":0.116282,"signal-number":2}} {"ts":"2020-07-15T22:17:41.354","pid":5492,"tid":"1498","sev":"info","req":"-","sess":"-","k":"drop-all-connections","v":{}} {"ts":"2020-07-15T22:17:41.356","pid":5492,"tid":"1a64","sev":"info","req":"-","sess":"-","k":"watchdog-stopped","v":{}} {"ts":"2020-07-15T22:17:41.356","pid":5492,"tid":"1bac","sev":"info","req":"-","sess":"-","k":"server-shutdown-begin","v":{"elapsed":0.00295336,"start-time-delta":0.119233}} {"ts":"2020-07-15T22:17:41.356","pid":5492,"tid":"1bac","sev":"info","req":"-","sess":"-","k":"background-scheduler-shutdown","v":{}} {"ts":"2020-07-15T22:17:41.356","pid":5492,"tid":"1bac","sev":"info","req":"-","sess":"-","k":"background-scheduler-shutdown-end","v":{"elapsed":0.000205857}} {"ts":"2020-07-15T22:17:41.356","pid":5492,"tid":"1bac","sev":"info","req":"-","sess":"-","k":"scheduler-shutdown-begin","v":{}} {"ts":"2020-07-15T22:17:41.358","pid":5492,"tid":"1bac","sev":"info","req":"-","sess":"-","k":"scheduler-shutdown-end","v":{"elapsed":0.00140204}} {"ts":"2020-07-15T22:17:41.358","pid":5492,"tid":"1bac","sev":"info","req":"-","sess":"-","k":"global-infrastructure-shutdown","v":{}} {"ts":"2020-07-15T22:17:41.358","pid":5492,"tid":"1bac","sev":"info","req":"-","sess":"-","k":"database-registry-shutdown-begin","v":{}} {"ts":"2020-07-15T22:17:41.358","pid":5492,"tid":"1bac","sev":"info","req":"-","sess":"-","k":"objstore-commit","v":{"isTemporary":false,"path":{"provider":"file","path":"\\?\D:\TEMP\hyper_db_PyCKfKnW"},"uncommitted-changes":false,"elapsed":9.021e-06}} {"ts":"2020-07-15T22:17:41.358","pid":5492,"tid":"1bac","sev":"info","req":"-","sess":"-","k":"objstore-close","v":{"path":{"provider":"file","path":"\\?\D:\TEMP\hyper_db_PyCKfKnW"},"mode":"read-write","had-cache-hit":false,"main-resource-size-bytes":65536,"written-bytes":0,"accessed-bytes":{"direct":1062,"indirect":0},"cache-read-bytes":0,"cache-write-bytes":0,"cache-resource-size-bytes":0,"elapsed":0.00060404}} {"ts":"2020-07-15T22:17:41.361","pid":5492,"tid":"1bac","sev":"info","req":"-","sess":"-","k":"dbregistry-release","v":{"name":"D:\TEMP\hyper_db_PyCKfKnW","saved":true,"elapsed-save":0.003395,"closed":true,"elapsed-registry-close":1.3123e-05,"elapsed":0.00341018}} {"ts":"2020-07-15T22:17:41.361","pid":5492,"tid":"1bac","sev":"info","req":"-","sess":"-","k":"database-registry-shutdown-end","v":{"elapsed":0.0034233}} {"ts":"2020-07-15T22:17:41.361","pid":5492,"tid":"1bac","sev":"info","req":"-","sess":"-","k":"server-shutdown-end","v":{"elapsed":0.00834091,"start-time-delta":0.12462}} {"ts":"2020-07-15T22:17:41.361","pid":5492,"tid":"1bac","sev":"info","req":"-","sess":"-","k":"logging-end","v":{}} {"ts":"2020-07-15T22:17:41.362","pid":5492,"tid":"e84","sev":"info","req":"-","sess":"-","k":"log-close","v":{"path":"\\?\D:\LogShark\Logs\hyperd.log"}}

I'm really not sure if the issue is because of Logshark or anything going fishy on that particular machine but VM having Logshark has 16 cores and 256 GB Memory.

Any assistance is really appreciated.

Thanks, Paramesh

Xantrul commented 4 years ago

Hi Paramesh,

Please try --plugins Replayer instead of --plugins ReplayCreation.

Paramesh40 commented 4 years ago

Thanks for the response, looks like its working. I could see logs being processed and no previous error. I will wait for it to complete and then update the thread but really thinks for quick response.

Regards, Paramesh

Paramesh40 commented 4 years ago

After running for 4 hours I could see json file generated but also an error message at Logshark, I'm going to give a try with the json file generated but looks like not all the logs were processed.

ERROR:

fail: LogShark.Plugins.PluginInitializer[0] Exception occurred while Replayer plugin was completing processing System.InvalidOperationException: Failed to compare two elements in the array. - --> System.NullReferenceException: Object reference not set to an instance of an object. at LogShark.Plugins.Replayer.ReplayerPlugin.<>c.b__30_0(B rowserSession s, BrowserSession t) at System.Collections.Generic.ArraySortHelper1.PickPivotAndPartition(T[] key s, Int32 lo, Int32 hi, Comparison1 comparer) at System.Collections.Generic.ArraySortHelper1.IntroSort(T[] keys, Int32 lo, Int32 hi, Int32 depthLimit, Comparison1 comparer) at System.Collections.Generic.ArraySortHelper1.IntrospectiveSort(T[] keys, I nt32 left, Int32 length, Comparison1 comparer) at System.Collections.Generic.ArraySortHelper1.Sort(T[] keys, Int32 index, I nt32 length, Comparison1 comparer) --- End of inner exception stack trace --- at System.Collections.Generic.ArraySortHelper1.Sort(T[] keys, Int32 index, I nt32 length, Comparison1 comparer) at System.Collections.Generic.List1.Sort(Comparison1 comparison) at LogShark.Plugins.Replayer.ReplayerPlugin.CompleteProcessing() at LogShark.Plugins.PluginInitializer.SendCompleteProcessingSignalToPlugins()

info: LogShark.LogSharkRunner[0] Completed reading log set and generating data info: LogShark.LogParser.TableauLogsExtractor[0] Disposing log extractor temporary files... info: LogShark.LogParser.TableauLogsExtractor[0] Log extractor temporary files disposed info: LogShark.LogSharkRunner[0] Plugins that had any data sent to them: Replayer info: LogShark.Writers.Hyper.HyperWorkbookGenerator[0] Starting to generate workbooks with results... fail: LogShark.LogSharkRunner[0] No workbooks were generated successfully. info: LogShark.Program[0]

  -----Summary-----
  Run ID 20071613254647-log failed

after running for 03:53:46.9323602. Reported problem: No workbooks were generat ed successfully. This problem is unexpected and it is not known whether or not it will go a way if LogShark is run again. Information below might contain more details on what exactly failed

  -----Processing errors-----
  No errors occurred while processing log set

  -----Generated workbooks-----
  Workbook templates available: Apache; Art; Backgrounder; ClusterController

; Config; Filestore; Hyper; Netstat; Postgres; ResourceManager; SearchServer; Se rverTelemetry; Tabadmin; Vizportal; VizqlDesktop

  -----Log Reading Statistics-----
  Processed zip file compressed size: 48,320 MB
  Plugins that received any data: Replayer

  Apache                                            : Processed 48 files in

00:02:47.1404911. Elapsed: 00:02:47.1404911. Total size: 1816 MB. Processing at 10.87 MB/sec VizqlserverCpp : Processed 137 files in 03:50:02.6818977. Elapsed: 03:50:02.6818977. Total size: 312737 MB. Processing at 22.66 MB/sec

  -----Data Writers Statistics-----

Xantrul commented 4 years ago

This looks like a known issue with Replayer plugin. The fix should be in the next 4.x release of LogShark, but in the meantime the workaround is to use older version of LS (https://github.com/tableau/Logshark/releases/tag/3.0.2)

Paramesh40 commented 4 years ago

Thanks for your response, I was able to get JSON file but when trying to run Replayer with Consolidate option set to 10 or 50 I see Replayer just running although there are only 65 sessions spread across for 3 days. I'm assuming Consolidate option is something which helps us in configuring to load session without wait time but I literally waited for more than 1 day before my session was logged off and existing session was terminated. Appreciate if you can further guide on this and thanks for your previous responses that helped in resolving the issues I was facing.

skostov-tableau commented 4 years ago

Hi Paramesh, Yes, the Consolidate option specifies the number of sessions you want to run per minute. I wonder if you could try the following:

Rather than replaying with the Consolidate option, try saving the altered (consolidated) sessions in a new Json file, and then load it and replay it. You should be able to see the session start and end time when you load it, so you can make sure those don't span a full day.

If that doesn't do what you want, check if you have an offset specified.

Hope this helps - let me know how this goes.

Best, Stoyko

Paramesh40 commented 4 years ago

Thanks for the response Stoyko, I was using the altered JSON file itself and running into issue. However I tried changing the user account and it started working which does not make sense as previous user account which I was using was also server admin on both the servers. I'm going to conduct bit more research on this after Replayer result analysis is done.

Thanks once again!

Regards, Paramesh

Paramesh40 commented 4 years ago

Hi Stoyko,

Although I was able to run Replayer with multiple Consolidate value when using multiple user accounts looks like sessions are not being triggered and all I see is Null values and failed sessions in Replayer. Other thing which I wanted to clarify is that I'm seeing low number of sessions in JSON file although when checked in Apache there are more sessions in the logs of source server, so is there a way where we can understand about how Replayer identifies sessions and documentation of analyzing replayer results?

Also, adding to that I've question regarding user account being used for replaying Traffic i.e. I'm using SA which is server admin on the server but do not have access to underlying DB. Do we need to be using specific account having access to DB or can we use Tableau account having access to Tableau server? My understanding is that it has to be an account which has access to DB and also exist on Tableau site.

One strange thing which I noticed is that all the runs which are successful are with only account which is used as Server Run As Account in both source and Target server, apart from that if I use any other account then I'm getting failed sessions with 401 response code meaning we need to provide Tableau Run As account access to underlying DB if embedded credentials of reports or Data source are not picked up.

Thanks, Paramesh

Sammmmm commented 4 years ago

This (at least the NRE issue) should be resolved with the v4.2 release today

Paramesh40 commented 4 years ago

You mean new version is being released today and that has the fixes, can you please clarify regarding what fixes you are referring and with 4.2 I was running into issue where I couldn't generate JSON file because of which had to use 3.0.2 based on the community recommendation.

Xantrul commented 4 years ago

Hi Paramesh,

We released LogShark 4.2 that has a fix for the original issue in this thread - the one preventing you from generating JSON file using LogShark 4.1.2. If you have a chance - please try new version of LogShark and let us know if it you were able to generate JSON successfully.

As for the other issue in this thread - the one about using generated JSON file - new release does not address it (at least not explicitly). I would still try to re-generate JSON using 4.2 and try it with Replayer to see if it works better (i.e. in case LogShark 4.x plugin outputs slightly different JSON)

Paramesh40 commented 4 years ago

Thanks for the response, however it would be a great help if you can clarify regarding below query.

" Also, adding to that I've question regarding user account being used for replaying Traffic i.e. I'm using SA which is server admin on the server but do not have access to underlying DB. Do we need to be using specific account having access to DB or can we use Tableau account having access to Tableau server? My understanding is that it has to be an account which has access to DB and also exist on Tableau site. "

skostov-tableau commented 4 years ago

Hi Paramesh,

I think the user you use for replaying traffic should have access to everything that's in that traffic, or it will fail. The Replayer doesn't have any special logic to bypass or handle situations where the original captured traffic succeeded, but the traffic being replayed may not.

Hope this answers your question - let me know if it doesn't.

Stoyko

Paramesh40 commented 4 years ago

Thanks for quick response Skostov, so I'm assuming that account being used in Replayer may not necessarily need to have access to underlying DB and regarding number of sessions I could see less sessions in JSON file when compared to Apache sessions of original logs, hence that question!

skostov-tableau commented 4 years ago

I think we are talking about 2 different tools here: one is the LogShark plugin, that should extract the sessions from the logs, and the other is the Replayer tool, that should replay the sessions extracted by the LogShark plugin.

The permissions are needed for the latter, during Replay. The extraction should have nothing to do with permissions; sessions are missing for other reasons - likely some of the log entries didn't parse successfully.

Please correct me if I misunderstood you.

Thanks Stoyko

Paramesh40 commented 4 years ago

What you said is correct Stoyko and here is what I'm doing. I'm processing one week logs using Replayer for Art, Apache and Replayer JSON file.

After processing when trying to run replayer with generated JSON file I could see X number of sessions which when verified against Apache logs there are more sessions. I was just curious to understand how replayer was calculating this sessions.

skostov-tableau commented 4 years ago

The easiest explanation I could give you is that in order to produce a list of sessions, Logshark parses Apache and Vizqlserver log lines and matches them based on session IDs. If there is an Apache line without matching lines in the vizqlserver logs, it will not produce a session. There are some commands that Logshark will skip - e.g. refresh-data-server, get-world-update, etc - about a dozen of them.

Paramesh40 commented 4 years ago

Thanks for the response Skostov.

On the other note following the instructions I tried running updated Replayer set up 4.1.2 and ran into same issue. Looks like the bug is still not fixed.

fail: LogShark.Plugins.PluginInitializer[0] Exception occurred while Replayer plugin was completing processing System.InvalidOperationException: Failed to compare two elements in the array. - --> System.NullReferenceException: Object reference not set to an instance of an object. at LogShark.Plugins.Replayer.ReplayerPlugin.<>c.b__30_0(B rowserSession s, BrowserSession t) at System.Collections.Generic.ArraySortHelper1.PickPivotAndPartition(T[] key s, Int32 lo, Int32 hi, Comparison1 comparer) at System.Collections.Generic.ArraySortHelper1.IntroSort(T[] keys, Int32 lo, Int32 hi, Int32 depthLimit, Comparison1 comparer) at System.Collections.Generic.ArraySortHelper1.IntrospectiveSort(T[] keys, I nt32 left, Int32 length, Comparison1 comparer) at System.Collections.Generic.ArraySortHelper1.Sort(T[] keys, Int32 index, I nt32 length, Comparison1 comparer) --- End of inner exception stack trace --- at System.Collections.Generic.ArraySortHelper1.Sort(T[] keys, Int32 index, I nt32 length, Comparison1 comparer) at System.Collections.Generic.List1.Sort(Comparison1 comparison) at LogShark.Plugins.Replayer.ReplayerPlugin.CompleteProcessing() at LogShark.Plugins.PluginInitializer.SendCompleteProcessingSignalToPlugins()

info: LogShark.LogSharkRunner[0] Completed reading log set and generating data info: LogShark.LogParser.TableauLogsExtractor[0] Disposing log extractor temporary files... info: LogShark.LogParser.TableauLogsExtractor[0] Log extractor temporary files disposed info: LogShark.LogSharkRunner[0] Plugins that had any data sent to them: Replayer info: LogShark.Writers.Hyper.HyperWorkbookGenerator[0] Starting to generate workbooks with results... fail: LogShark.LogSharkRunner[0] No workbooks were generated successfully. info: LogShark.Program[0]

  -----Summary-----
  Run ID 20072914043948-abc-16 failed

after running for 00:03:41.8016351. Reported problem: No workbooks were generat ed successfully. This problem is unexpected and it is not known whether or not it will go a way if LogShark is run again. Information below might contain more details on what exactly failed

  -----Processing errors-----
  No errors occurred while processing log set

  -----Generated workbooks-----
  Workbook templates available: Apache; Art; Backgrounder; ClusterController

; Config; Filestore; Hyper; Netstat; Postgres; ResourceManager; SearchServer; Se rverTelemetry; Tabadmin; Vizportal; VizqlDesktop

  -----Log Reading Statistics-----
  Processed zip file compressed size: 1,335 MB
  Plugins that received any data: Replayer

  Apache                                            : Processed 12 files in

00:00:11.5301211. Elapsed: 00:00:11.5301211. Total size: 128 MB. Processing at 1 1.10 MB/sec VizqlserverCpp : Processed 24 files in 00:03:27.6409746. Elapsed: 00:03:27.6409746. Total size: 4435 MB. Processing at 21.36 MB/sec

  -----Data Writers Statistics-----

skostov-tableau commented 4 years ago

Hi Paramesh,

Did you update to version 4.2, or 4.1.2? The fix should be in 4.2.

Paramesh40 commented 4 years ago

Sorry, I thought I was using 4.2. Let me run 4.2 and test it.

Paramesh40 commented 4 years ago

Same issue even with 4.2, still throwing the error. :(

Paramesh40 commented 4 years ago

Hi All,

After running many iterations of Replayer I'm struggling to correlate the number of sessions which I'm seeing in Replayer i.e. there are many less sessions being run when replayed compared to original sessions and I'm really not sure how to validate if traffic replayed is correct or wrong.

Is there any way even in Logshark to identify the number of sessions on source server for particular set of logs and then compare them with Target server loghsark logs after running Replayer.

Also, I'm only able to run Replayer with single user and not multiple accounts. Is there any better documetation or a thread that explains all the functionalities of Replayer?

Appreciate your response.

Thanks, Paramesh

skostov-tableau commented 4 years ago

Hi Paramesh,

Following up on your 3 questions above:

Regarding the error in 4.2: Does it produce exactly the same call stack, starting with

--> System.NullReferenceException: Object reference not set to an instance of an object. at LogShark.Plugins.Replayer.ReplayerPlugin.<>c.b__30_0(BrowserSession s, BrowserSession t)

and ending with at LogShark.Plugins.Replayer.ReplayerPlugin.CompleteProcessing()?

Please confirm.

Regarding number of sessions, I'm still a bit confused about what kind of difference you observe. You have logs from source server; running Logshark extracts X number of sessions. Do you think X is incorrect, or do you think that once you replay those X sessions against a target server, you now see a smaller number Y? Please clarify.
Regarding multiple accounts, I believe you need to do the following:
- Once you start the Replayer tool, in the Replay Options tab, check Http (Multi User)
- In the Auth tab, check "Use multiple user accounts". Those will now be taken from file config/userpool.csv in your Replayer directory. I think this has header "UserName,Password,UserType", so your entries should look like 'user,pwd,ViewerOrInteractor'. Give it a try and let me know if it doesn't work. I'm not sure if it's documented somewhere; I would need to ask my colleagues.

Hope this helps at least with some of your questions. Thanks! Stoyko

psangang commented 4 years ago

Hi Stoyko,

PFB my responses.

1.I dont see same exact call stack, Attaching the log file for your reference.

What I'm saying is after I use logshark to generate JSON file and when I load JSON file for running user traffic Replayer shows Y number of sessions which appears to be very less. I looked into source server Apache and Art workbooks and can confirm that there are more sessions that whats displayes in Replayer when JSON file is loaded.

Not just this what I'm saying is after processing source server logs through Logshark I'm using Apache workbook to identify sessions but based on your previous response it looks like thats not the right place to even look at to identify correct sessions of source server which I can then use to compare with Target server after replaying. Do you know where I can get this information from the existing Logshark logs?

LogShark-20200731.log

Yes, I followed the same exact step and below is format I'm following.

username, password, ServerAdmin as role name.

Please let me know if you need more clarification.

Thanks, Paramesh

skostov-tableau commented 4 years ago

Thanks for your responses! Here's some direction for what to do next:

I didn't see a null reference exception in the log you attached, so this issue is fixed. The reported error that no workbook is generated is of no concern - it's not expected to be generated for this plugin. I did see some exceptions during parsing, but those shouldn't affect the generation of a json file. Worst thing they could cause is the loss of some sessions.

Do you have concerns with this version? Did it not generate a json file?

Open the json file generated by Logshark in a text editor, e.g. Notepad++, and count "BrowserStartTime". This should give you the number of sessions that were extracted - e.g. X. Now, load this json file in Replayer - it should report how many sessions it loaded. You claim that this number Y is way less than X, correct? Please confirm. If that's what you observe, I am not certain of the reasons; I will need to ask colleagues.

Pay attention to any filters that the Replay tool may have in place. Here's the output for me when I loaded a json file with 9 sessions: INFO [2020-07-31 12:28:10,994][AWT-EventQueue-0] (PlayBack.java:370) - Filter user =null INFO [2020-07-31 12:28:10,994][AWT-EventQueue-0] (PlayBack.java:371) - Filter Access Request ID =null INFO [2020-07-31 12:28:10,994][AWT-EventQueue-0] (PlayBack.java:372) - Filter start time =null INFO [2020-07-31 12:28:10,994][AWT-EventQueue-0] (PlayBack.java:373) - Filter End time =null INFO [2020-07-31 12:28:10,994][AWT-EventQueue-0] (PlayBack.java:779) - Filtered browser sessions : 9

I think the Replay tool has it hard-coded somewhere to look for non-server-admins. Change ServerAdmin in the config to ViewerOrInteractor and give it a try again; let me know what happens. (The actual role on the server is irrelevant to Replayer; worst thing that could happen is a login failure if permissions are not sufficient.)

Paramesh40 commented 4 years ago

Hi Skostov,

Thanks for your update, I did look for "BrowserStartTime" in generated JSON file and compared with Replayer command and could see that all browser session count is matching with text editor count but not with filtered browser session and this filtered browser session is less for e.g. Text Editor count is 2001, all browser sessions count is 2001 but filtered sessions count is 1001 and I'm assuming that Replayer only plays this filtered sessions. But, why is the filtered browser session low, is it because it cannot replay them due to some issues and filtering it before running?

Secondly, the session count I was talking about was not exactly the one which you mentioned.

For e.g. I've source Server A, processed logs of those servers to generate JSON file which shows 1001 filtered sessions and replayer replays them but my question was does this sessions captured in JSON are accurate and how can we compare those sessions with the sessions of Server A. The reason I ask this is because when I check the Apache workbook of logs processed through logshark using which JSON was generated I see sessions around 8000 and I wanted to validate Replayer session count with Original logset session count.

Regarding multiple user session, let me give a try.

Hope the above explanation make sense. if not let me know I will try to put it other way.

Thanks, Paramesh

skostov-tableau commented 4 years ago

Thanks! Yes, your explanation makes sense - we are getting somewhere with the filters. Maybe you have some filters defined in the tool.

Do you see an output like the one I showed above? It lists all filters that Replayer would apply. If they are all set to null, that means it doesn't apply any filters.

If they are all set to null and you still get some sessions filtered, there could be something wrong with the session. E.g. some field could be missing or set to null. I wonder if it would be easy for you to find a session in the text file that doesn't load in Replayer and provide it here - it could give me some insight why it's filtered.

I also wonder if some sessions could have the same session ID, though I can't imagine why that would happen. But if it did happen, Replayer will probably not display all - it may drop all but the first with that ID.

I'm just making guesses here though. On Monday I could try asking experts, but until then, let's try to troubleshoot as much as we can ourselves.

Paramesh40 commented 4 years ago

Hi Skostov,

I dont see any filter applied but still as you could see below sessions are filtered. I do not understand what you mean by identifying a sessions in text file that doesn't load in Replayer. Can you tell me how to do that?

Selected File Selected File D:\Logshark -3.0.2\Output\Playback_2007-23-38-14.json Reading and replaying session from Json file D:\Logshark -3.0.2\Output\itsusraws p00225_20072016255933_testserver\Playback_2007-23-38-14.jso n INFO [2020-07-31 18:48:07,112][AWT-EventQueue-0] (PlayBack.java:670) - Readin g and replaying session from Json file D:\Logshark -3.0.2\Output\testserver\Playback_2007-23-38-14.json Reading and replaying session from Json file D:\Logshark -3.0.2\Output\itsusraws p00225_20072016255933_testserver\Playback_2007-23-38-14.jso n INFO [2020-07-31 18:48:08,050][AWT-EventQueue-0] (PlayBack.java:867) - Return filtered sesssion from D:\Logshark -3.0.2\Output\itsusrawsp00225_2007201625593 3_testserver\Playback_2007-23-38-14.json INFO [2020-07-31 18:48:08,051][AWT-EventQueue-0] (PlayBack.java:670) - Readin g and replaying session from Json file D:\Logshark -3.0.2\Output\itsusrawsp00225 _20072016255933_Playback_2007-23-38-14.json INFO [2020-07-31 18:48:08,902][AWT-EventQueue-0] (PlayBack.java:869) - All br owser sessions : 2001 INFO [2020-07-31 18:48:08,902][AWT-EventQueue-0] (PlayBack.java:376) - Filters set INFO [2020-07-31 18:48:08,904][AWT-EventQueue-0] (PlayBack.java:377) - Filter user =null INFO [2020-07-31 18:48:08,904][AWT-EventQueue-0] (PlayBack.java:378) - Filter Access Request ID =null INFO [2020-07-31 18:48:08,905][AWT-EventQueue-0] (PlayBack.java:379) - Filter start time =null INFO [2020-07-31 18:48:08,905][AWT-EventQueue-0] (PlayBack.java:380) - Filter End time =null INFO [2020-07-31 18:48:08,921][AWT-EventQueue-0] (PlayBack.java:872) - Filter ed browser sessions : 1003

skostov-tableau commented 4 years ago

OK, so you don't have filters that you defined (everything is set to null), but still about half of the sessions get filtered out.

One possibility I just noticed: Replayer UI has "Skip img sessions" and "Skip alert sessions". Uncheck those to see if you get a closer number.

If still not, let's try to identify a session that is not loaded by Replayer. Try this: load the json file in Replayer, and at the same time, open it in a text editor, e.g. Notepad++.
In Replayer, the sessions will probably be ordered by RequestID or time. Take the first RequestID from what is loaded in Replayer, and find it in the text file. Make sure it appears exactly once there. If there is a session in the text file before this one, it wasn't loaded in Replayer - double-check that by taking its Request ID (e.g. "AccessRequestID": "XdcVEV05fxiumRBVnbROFAAAA5Y"), put it in the RequestId field in the Replayer UI, check "Filter", and confirm that it's not loaded.

If not, take the second RequestID from Replayer, find it in the text file, make sure there's no gap between the first and the second. Continue until you find a missing one. If many sessions at the beginning are in the same order, try searching from the end... but given that Replayer filtered out about half of your sessions, it shouldn't be too hard to find one that was not loaded.

Save that session in a file and upload it here. I'll try to understand why it was filtered out.

Paramesh40 commented 4 years ago

Hi Skostov,

I tried searching for the missing sessions and here are the steps I followed.

Loaded JSON file in Replayer and then tried searching for Request ID's from Replayer UI in JSON file loaded in Text Editor. I could see only one entry of the request ID in text editor and surprisingly all the request ID's are available in Text Editor. Doing other way i.e. randomly selected some request ID's from JSON file loaded in Text editor and when searched in Replayer UI they are available too. So, honestly I dont think there is an easy way to identify missing sessions. Unchecking "Skip img sessions" and "Skip alert sessions" did not make any difference.

Secondly, the main question still remains unanswered i.e. lets say Replayer was able to display some X number of sessions(lets not talk about filtered for now and hoping that X number is all sessions Replayer was able to identify), what I'm asking is how do we even verify if this X number of sessions are correct number i.e. my logs of source server A shows many apache sessions and number displayed in apache workbook are totally different when compared with session number of Replayer.

Let me give you little background of what I'm trying to achieve.

I've source Server A which is a PROD server and I want to replay the traffic on other server and then compare the results. Considering the scenario we are trying to achieve below are the open queries:

How to check the sessions of Source Server A and compare with Replayer Sessions ?
After Replayer loading the sessions how to analyze the results of Replayed sessions with PROD sessions i.e. definitely the pattern would be differing since traffic would be distributed across days on PROD server compare to test server where we are trying to replay 2-3 days of traffic in just hours by adjusting consolidate value?
Regarding analysis of the results, since request ID and session ID of both PROD and test server would not be same how should I proceed with identifying the sessions to compare them i.e. lets say there are 10 user sessions for report R in PROD server and after replayer assuming that there were 10 sessions even in Replayer traffic how do I select one session among 10 and compare them?

In addition to above after replayer is run I could see that all the interactions shown on test server or replayer workbook as failed interactions, does this interactions correlate to user activity of changing the filter or navigating to other sheet, etc? and if so all I could see is report load time with all interactions shown as failed?

Also, regarding the consolidate value I'm not sure what value to specify and how does it replay i.e. I'm having 2-3 days logs and adjusting value to 10, 20, 50 but is there any thing that can explain how the consolidate exactly works rather than just specifying that it tries to load some number of sessions per minute i.e. if there is a user activity at 10 PM and no user activity until 4 AM and adjusting consolidate value to 2 , does that reduce the wait time to 3 hours instead of waiting for 6 hours for it replay sessions?

Does making consolidate value to 3 reduces wait time to 2 hours and so on?

Another thing regarding JSON file of 4.2:

I've been working with Logshark 3.0.2 to generate JSON file and after updating to 4.2 although as you mentioned there might be error of no workbooks generated and when I went further to load the file to replayer below is what I see.

Selected File D:\LogShark.Win.4.2\ReplayerOutput\Playback_3107-16-20-45.json Reading and replaying session from Json file D:\LogShark.Win.4.2\ReplayerOutput\ Playback_3107-16-20-45.json INFO [2020-08-02 08:33:19,399][AWT-EventQueue-0] (PlayBack.java:670) - Readin g and replaying session from Json file D:\LogShark.Win.4.2\ReplayerOutput\Playba ck_3107-16-20-45.json Exception in thread "AWT-EventQueue-0" java.lang.OutOfMemoryError: Java heap spa ce at com.google.gson.stream.JsonReader.nextQuotedValue(JsonReader.java:100 1) at com.google.gson.stream.JsonReader.nextString(JsonReader.java:815) at com.google.gson.internal.bind.ObjectTypeAdapter.read(ObjectTypeAdapte r.java:76) at com.google.gson.internal.bind.TypeAdapterRuntimeTypeWrapper.read(Type AdapterRuntimeTypeWrapper.java:41) at com.google.gson.internal.bind.MapTypeAdapterFactory$Adapter.read(MapT ypeAdapterFactory.java:187) at com.google.gson.internal.bind.MapTypeAdapterFactory$Adapter.read(MapT ypeAdapterFactory.java:145) at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.read(Ref lectiveTypeAdapterFactory.java:129) at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.re ad(ReflectiveTypeAdapterFactory.java:220) at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.read(Ref lectiveTypeAdapterFactory.java:129) at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.re ad(ReflectiveTypeAdapterFactory.java:220) at com.google.gson.internal.bind.TypeAdapterRuntimeTypeWrapper.read(Type AdapterRuntimeTypeWrapper.java:41) at com.google.gson.internal.bind.CollectionTypeAdapterFactory$Adapter.re ad(CollectionTypeAdapterFactory.java:82) at com.google.gson.internal.bind.CollectionTypeAdapterFactory$Adapter.re ad(CollectionTypeAdapterFactory.java:61) at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.read(Ref lectiveTypeAdapterFactory.java:129) at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.re ad(ReflectiveTypeAdapterFactory.java:220) at com.google.gson.internal.bind.TypeAdapterRuntimeTypeWrapper.read(Type AdapterRuntimeTypeWrapper.java:41) at com.google.gson.internal.bind.CollectionTypeAdapterFactory$Adapter.re ad(CollectionTypeAdapterFactory.java:82) at com.google.gson.internal.bind.CollectionTypeAdapterFactory$Adapter.re ad(CollectionTypeAdapterFactory.java:61) at com.google.gson.Gson.fromJson(Gson.java:888) at com.google.gson.Gson.fromJson(Gson.java:853) at com.tableausoftware.test.tools.Replay.PlayBack.loadFromJson(PlayBack. java:676) at com.tableausoftware.test.tools.Replay.ReplayRunner.loadFromJson(Repla yRunner.java:2213) at com.tableausoftware.test.tools.Replay.ReplayRunner.recentOpenedReplay Select(ReplayRunner.java:687) at com.tableausoftware.test.tools.Replay.ReplayRunner$9.actionPerformed( ReplayRunner.java:562) at javax.swing.JComboBox.fireActionEvent(Unknown Source) at javax.swing.JComboBox.setSelectedItem(Unknown Source) at javax.swing.JComboBox.setSelectedIndex(Unknown Source) at com.tableausoftware.test.tools.Replay.ReplayRunner.loadSelectedReplay File(ReplayRunner.java:2292) at com.tableausoftware.test.tools.Replay.ReplayRunner.chooseReplayLog(Re playRunner.java:2243) at com.tableausoftware.test.tools.Replay.ReplayRunner.access$1100(Replay Runner.java:124) at com.tableausoftware.test.tools.Replay.ReplayRunner$6.actionPerformed( ReplayRunner.java:441) at javax.swing.AbstractButton.fireActionPerformed(Unknown Source)

skostov-tableau commented 4 years ago

Hi Paramesh,

I checked with one of our experts, and he basically confirmed my assumptions and gave some clarification as to why filtering is happening.

Regarding more Apache logs than Browser sessions: not all Apache logs result in Browser sessions. The latter are a combination of Apache and Vizqlserver logs (think of it as a join on session ID). So if there are no Vizqlserver logs for a particular session ID, you won't see a Browser session either.
Regarding filtered Browser sessions when loaded from the json file: As I suspected, that's due to duplicated sessions. Our expert explained that this is due to reusing a session due to caching. So what you observe basically means that roughly half of your sessions were reused due to caching. When comparing results, I would advise comparing the non-cached sessions only (and those are the ones you would be replaying as well).
Consolidation does 2 things: it fits the sessions according to the rate per minute you specified, and also makes the wait time between them the same. The wait time will not be preserved or kept proportional; if you have 1000 sessions, but only between 2 of them the wait is 6 hours, if you consolidate to 20 sessions per minute, the wait time between any 2 consecutive will be 3 seconds (60/20).
Looks like your json is too large to load in your system. I wonder if you could split it into 2 parts using a text editor before trying to load into the Replay tool.

Hope this helps! Stoyko

Paramesh40 commented 4 years ago

Thanks for the update Stoyko, so as per explanation whatever the session number we are seeing in JSON is correct but the reason why I was focusing more to identify the correct number of sessions was because of less number of sessions i'm seeing in JSON or Replayer i.e. entire JSON file shows 1003 filtered sessions but when I restricted on a single site it just showed 65 sessions which I'm sure that the number is too less.

Regarding duplicated sessions being filtered out can you elaborate what do you mean by reusing session due to caching? We would be using the non-cached sessions for comparing results but how do we identify the sessions from the source server to compare with when Source Server Logs show different patter or more sessions?

I will try to split the JSON file and check if that helps.

Is there any way we can get hold of product team so that it would be easier to demonstrate the issue?

Paramesh40 commented 4 years ago

Adding to above when I triggered Replayer of 1003 session with Consolidate value of 100 I just see that it still running and its already around 30 hours since Replayer is running and traffic is distributed among 2 and half days. So with Consolidate value of 100 the wait time between any two consecutive will be 0.6 seconds but its just running continuously.

Paramesh40 commented 4 years ago

In addition to that other thing which I noticed is of when trying to run http i.e. browserless traffic under Debug I dont see the options being enabled to control the traffic and I'm not sure if its because we are running it "Play Speed as recorded"?

UmapathiM001 commented 4 years ago

with http option the tool does not allow controlling the play speed, that is only for Browser(Chrome) option. You should use "consolidate" option if you want to squeeze the sessions closer, save the consolidated replay file and rerun it.

skostov-tableau commented 4 years ago

Hi Paramesh,

Regarding the duplicated sessions: When you load your Json in Replayer, each session will have a Request ID, e.g. XdcVEV05fxiumRBVnbROFAAAA5Y. When you open your Json in a text editor, you'll see a line like "AccessRequestID": "XdcVEV05fxiumRBVnbROFAAAA5Y" for each browser session that's there.
In Replayer you'll never see the same Request ID twice. If you see the same Request ID twice in the Json file (text editor), this means that the second one (with later execution time) was using the cached session. This one won't be loaded in Replayer.
The only reason I can think of why you see a long wait after you use consolidate is that you have a long running session... Can you save the consolidated json file (but don't replay it yet) and verify in a text editor that the start times are spread accordingly?

UmapathiM001 commented 4 years ago

This might be a defect, please verify the session time of consolidated replay file in Replayer tool. We should discuss about sharing your replay file if you still have any issue.

Paramesh40 commented 4 years ago

Thanks for the response Umapathu, does the altered JSON file shows start time in sorting order so that I can just check first start time and last start time to confirm the range?

Paramesh40 commented 4 years ago

When I checked last time I could only see one request ID even in JSON file loaded in text editor but let me double check to confirm if the request ID are displayed multiple times.

UmapathiM001 commented 4 years ago

it is sorted by time.

UmapathiM001 commented 4 years ago

Small correction 1) Request ID or AccessRequestID is never repeated in the Replay json file, "VizqlSession" ID could get repeated and Replayer drops it as duplicate.

Paramesh40 commented 4 years ago

So, in order to identify if the filtered traffic is correct we need to chase the session ID to see how many duplicates of them exist.

@UmapathiM001 ,

Can you please respond regarding Interactions and multi-user thing Umapathi. I just tested multi-user with Interactor role and can confirm that out of 65 sessions only 22 requests were loaded and the one went successful are with SA. Looks like there is no way to Replay traffic with multiple users. And, even for successful requests that went through Replayer workbook shows all interactions as failed.

psangang commented 4 years ago

Failed_Interactions

Paramesh40 commented 4 years ago

Yeah, I did check and they are sorted. Now after me loading or filtering the JSON file having 2001 sessions of which filtered sessions are 1001 when setting Consolidate value to 60 I could see filtered JSON file showing correct timestamp with 1 second duration between each request and below are the beginning and ending time interval.

Based on below times can I assume that Replayer is going to complete in below time interval although sessions might be erroring due to less number of vizql but I just want to run and see to get better understanding so that I can tweak the value.

"BrowserStartTime":"2020-08-05T21:47:00.940Z" "BrowserStartTime":"2020-08-05T22:20:20.940Z"

UmapathiM001 commented 4 years ago

There are many issues you have mentioned here

when interactions fail with http replay option you should try replaying single session with chrome browser option in Replayer UI, you can go to the Debug tab and click Next to perform each action, this will help you understand why interactions fail.
For multiusers test runs you need to use userpool.csv with all the test user accounts, please refer to Replayer community page https://community.tableau.com/s/news/a0A4T000002O44aUAC/using-replayer
About number of sessions getting filtered from 2001 to 1001, we would like to confirm why many sessions are getting skipped. If you can share the files via Tableau TAMs that would be great.

psangang commented 4 years ago

@UmapathiM001 ,

Thanks for your response, will try to run single sessions and debug. Regarding multiple users, kindly note that I've been using userpool.csv with multiple account in the format userid, password, role which I was using server admin initially but after response in github changed it to Interactor and still can see sessions only with one Service Account.

PFB snapshot for your reference. Multiple_Users

Let me get in touch with TAM about sharing the JSON file.

psangang commented 4 years ago

@UmapathiM001 ,

Can you help getting some clarification on this too, after filtering based on Consolidate value 60 I could see wait time as 1 second now but based on above time stamp Replayer dint finish loading traffic in 33 minutes. So, not sure exactly how the traffic is pushed although JSON if updated with correct timestamp.

skostov-tableau commented 4 years ago

We have a list of commands that we don't want to replay, so we don't include them in the json file. We call those "skippable commands". A list can be found under LogShark\Config, there should be a LogSharkConfig.json file.

I can make one suggestion to update the skippable commands that logshark would exclude when creating the json. Find the "SkippableCommands" entry in the json file above, and add the following 2: "tabdoc:get-button-object-pres-model", "tabdoc:get-schema-viewer-pres-model" Then run logshark again.

This change will be available with the next release of Logshark, but until then, you can do it manually.

Thanks Stoyko

UmapathiM001 commented 4 years ago

Did you select the "User multiple user accounts" check box in Auth tab? by the way running with multiple user accounts is not a critically important step for load testing.

Paramesh40 commented 4 years ago

@UmapathiM001 , Yes I've used multiple user accounts.

tableau / Logshark

Issue Creating Replayer JSON File with Logshark 4.1.2 #123