UncleGedd
commented
2 years ago Hi @EandrewJones ! Thanks for raising the issue, will take a look tomorrow
Closed EandrewJones closed 2 years ago
UncleGedd
commented
2 years ago Hi @EandrewJones ! Thanks for raising the issue, will take a look tomorrow
UncleGedd
commented
2 years ago Ok, my theory on the empty entries in the local json logs is that the issus lies over in server.js where it's adding the , delimiter.
As for your first example:
"message" => "[{\"target\":\"div.post\",\"path\":[\"div.post\",\"li\",\"ul\",\"div.main\",\"div\",\"div#socialMediaTabpanel_0.squawker
selected\",\"div#socialMediaTabpanelcontainer\",\"div#socialMediaTabcontainer\",\"div.wrapper socialMedia\",\"div.content
\",\"div#pnSocial media.pane social-media\",\"div#workspace\",\"main\",\"div#app\",\"body\",\"html\"],\"datasets\":[{\"posterId\":\"42948
\"},{\"postId\":\"2682\",\"tweetId\":\"861283517715623938\",\"lastViewStarted\":\"4789.38\",\"hasIntersected\":\"true\"},{\"platformId\":\"54
\"},{\"moduleName\":\"socialMedia.tabs\"},{\"componentTypeId\":\"7\"}],\"pageUrl\":\"https://www.icons.umd.edu/devicons
/ui_html.shell?p_sid=1343376885&p_lang=fr\",\"pageTitle\":\"INCAS | ICONSnet\",\"pageReferrer\":\"\",\"browser\":{\"browser\":\"firefox
\",\"version\":\"99.0.0\"},\"clientTime\":1650569081343,\"microTime\":0,\"location\":{\"x\":885,\"y\":505},\"scrnRes\":{\"width\":1294,
\"height\":893},\"type\":\"mouseover\",\"logType\":\"raw\",\"userAction\":true,\"details\":null,\"userId\":\"test-evan-userale-2.3.0\",
\"toolVersion\":\"2.2.0\",\"toolName\":\"ICONSnet Social Media Simulator\",\"useraleVersion\":\"2.2.0\",\"sessionID
\":\"session_1650569061161\",\"isPost\":true,\"postIds\":[\"861283517715623938\"]},null,null,null]",Are you sending the payload directly from the frontend Userale client to Logstash?
poorejc
commented
2 years ago @EandrewJones Hi! Thanks for the ticket!
A few more questions:
You say that the nulls are "breaking" logStash Parsing. Can you clarify a bit what you mean there? Are you getting dropped logs? Or are you just getting errors like the legacy "grokparsefailure" from Logstash?
What version of Logstash are you using? 6.8 or 7+ (note that we'll be moving to 7.8 soon, and have a working backend that will be moved over to Apache--this is a different build than the previous (@apache-flagon repo) build. See here.
Are you using modified your own modified Logstash parsers/plugins?
Which version of UserALE.js you are using? 2.2.0 or testing at 2.3.0? If 2.30, did you notice the same behavior in 2.2.0?
Can you tell me a bit more about how you generated that first log. I'm guessing this is the view of the message from LogStash... There are some fields I'm not familiar with, e.g., postIds. logType=="raw", yet there are new fields added. Is this a custom log of sorts? or is there decoration through userale.map API? Any customer AuthHeaders added?
Regarding null and LogStash... We are aware that fields with null values aren't parsed, particularly in fields like location and details. Examples (I used 2.2.0 to generate this, as the toolVersion in your logs is 2.2.0):
Here is a submit log from the Example page from the example server (server.js):
{
target: 'form#test_text_input',
path: [ 'form#test_text_input', 'body', 'html', '#document', 'Window' ],
pageUrl: 'file:///
pageTitle: 'UserALE.js - Example Page',
pageReferrer: '',
browser: { browser: 'chrome', version: '100.0.4896' },
clientTime: 1650762410279,
microTime: 0.3,
location: { x: null, y: null },
scrnRes: { width: 1280, height: 577 },
type: 'submit',
logType: 'raw',
userAction: true,
details: null,
userId: 'me',
toolVersion: '2.2.0',
toolName: 'Apache UserALE.js Example (Custom)',
useraleVersion: '2.2.0',
sessionID: 'session_1650636958755'
}details and location both include null values.
Here is a submit log in Elasticsearch (in JSON):
{
"_index": "userale",
"_type": "_doc",
"_id": "vGAKWYABe4GJJBS6pZlw",
"_version": 1,
"_score": null,
"fields": {
"logType": [
"raw"
],
"userAction": [
true
],
"microTime": [
0
],
"pageTitle": [
"UserALE.js - Example Page"
],
"patch_ver": [
0
],
"browser.browser": [
"chrome"
],
"sessionID": [
"session_1650636958755"
],
"type": [
"submit"
],
"clientTime": [
"2022-04-24T00:48:31.457Z"
],
"scrnRes.width": [
1280
],
"userId": [
"me"
],
"target": [
"form#test_text_input"
],
"scrnRes.height": [
577
],
"minor_ver": [
2
],
"path": [
"form#test_text_input",
"body",
"html",
"#document",
"Window"
],
"toolVersion": [
"2.2.0"
],
"browser.version": [
"100.0.4896"
],
"@timestamp": [
"2022-04-24T00:48:31.495Z"
],
"useraleVersion": [
"2.2.0"
],
"host": [
"172.20.0.1"
],
"major_ver": [
2
],
"pageUrl": [
"file:///C:/
],
"pageReferrer": [
""
],
"toolName": [
"Apache UserALE.js Example (Custom)"
]
},
"highlight": {
"type": [
"@kibana-highlighted-field@submit@/kibana-highlighted-field@"
]
},
"sort": [
1650761311457
]
}Those fields are noticeably absent, although we're still getting submit logs.
I generated these from the exact same test page... Elastic is dropping dropping fields with null values (which is an indexing issue--the value null doesn't conform to our index. I think LogStash does actually parse null as nil, but they're dropped from the ELK index. So far, this has been fine b/c if its null its not really essential to have that data (although can create issues in edge cases for back end analyses).
The null values I see in your logs output are as expected. Also, I think @UncleGedd is right about the empty lines after submit events--submit events trigger a page reload that is likely to blame for that empty line given how server.js works. However, I would like to figure out your first example, though. I've never seen null keys like that before in a UserALE log--very interested in how it was created.
Happy to help out! Please answer those questions above as they'll be useful to us in doing forensics.
Thanks again @EandrewJones !
poorejc
commented
2 years ago Update:
This might be a grokparsefailure on tags that we add to logs with grok in logstash.conf.
We parse the semantic version string of useraleVersion and toolVersion and add additional fields. However, it looks like only useraleVersion is being correctly parsed (I honestly can't remember why we're parsing this)--you'll see these fields in LogStash as minor_version, patch_version... and so forth. There should also be a tool_minor_version and tool_patch_version... not so. I see grokparsefailure messages. It could be the 3 null entries are failed tags. Note that they fall outside of the log payload braces...
It could be other tags that LogStash adds by default for ELK indexing that grok filters are being applied to. Here's a message I see, for example:
{
"tags" => [
[0] "_grokparsefailure"
],
"@timestamp" => 2022-04-24T02:07:34.612Z,
"port" => ,
"host" => "gateway"
}We also mutate logs to remove headers, for example. However, these wouldn't be a part of the message payload. Not sure if that would result in the message you're seeing...
This is my best guess at this point without more information about how that log was generated (at exactly which stage in the pipeline you're looking), and what the consequences of the parsing failure is (dropped log, dropped field, etc.).
EandrewJones
commented
2 years ago @UncleGedd I am sending the logs directly from UserALE to a logstash endpoint. I do have one custom JS script in which I send custom logs via userale when triggered by an intersection observer event, but I was encountering this issue even prior to adding that.
@poorejc Yes, it's very odd. I've been debugging this on an off since December and nothing has worked.
- You say that the nulls are "breaking" logStash Parsing. Can you clarify a bit what you mean here? Are you getting dropped logs? Or are you just getting errors like the legacy "grokparsefailure" from Logstash?
The reason I thought/think userale was sending null events was because I did some testing and it didn't appear that any logs were being dropped. The message arrays with nulls get stored in ES still. I managed to parse, extract and calculate aggregate mouseover times from those in python and it matched exactly with my session behavior. But now I'm not sure whether the nulls are entirely missing logs.
- What version of Logstash are you using? 6.8 or 7+ (note that we'll be moving to 7.8 soon, and have a working backend that will be moved over to Apache--this is a different build than the previous (@apache-flagon repo) build. See here.
I'm using logstash and ES 6.8. The ES instance is hosted through AWS opensearch service and I'm running my own logstash docker image on an ec2 instance. This problem also happened when I was running both locally in docker images.
- Are you using modified your own modified Logstash parsers/plugins?
No. I'm essentially using the exact logstash.conf file as provided in your examples. I recently added another route and port to conditionally send another set of logs to a different ES index, but this issue long pre-dates that.
- Which version of UserALE.js you are using? 2.2.0 or testing at 2.3.0? If 2.30, did you notice the same behavior in 2.2.0?
2.2.0
- Can you tell me a bit more about how you generated that first log. I'm guessing this is the view of the message from LogStash... There are some fields I'm not familiar with, e.g., postIds. logType=="raw", yet there are new fields added. Is this a custom log of sorts? or is there decoration through userale.map API? Any customer AuthHeaders added?
Correct, that was clipped from logstash logs. So I user userale.map API to decoraate the logs with two custom fields, isPost: boolean and postIds: string[] | number[] using another function for extracting specific information from an element's datasets if they exist:
/** addPostInfo
* A callback function to be passed to userale.map(...) that adds
* post metadata to logs for post elements
*
* @param {Object} log UserALE log
* @returns {Object} UserALE log
*/
function addPostInfo(log) {
if (typeof log.path !== "undefined") {
if (log.datasets.length > 0) {
let postIds = postDetector.postIdExtractor(log.datasets);
if (postIds.length > 0) {
return Object.assign({}, log, {
isPost: true,
postIds: postIds,
});
}
} else {
return Object.assign({}, log, {
isPost: false,
});
}
}
}
window.userale.map(addPostInfo);The parse failure might be related to those tags, but I can say that it is not consistently three nulls in the message array. It's usually 1-3.
poorejc
commented
2 years ago @EandrewJones thanks! This is great context.
After I read this, I'm still leaning on those nulls being tags... in fact, they could actually be grokparsefailure tags. Anytime a given message wasn't parsed correctly by a given filter, etc., you get a grokparsefailure added to tags... That's to say that I'm not sure UserALE.js is injecting the nulls at the end of the message.
Nonetheless, I'll do a little more digging into this...
One thing that I should mention is that LogStash actually creates something like a NiFi "flowfile". Meaning what gets sent to ELK isn't the original message, but new JSON. In fact, if you're using our Flagon example 6.8 ELK build, if you look in the Pipeline dir under Logstash, you'll find that we actually mutate our the original message payload and headers from the "flowfile", so that the original message payload isn't posted to Elastic (would be added to index under "message" key), in addition to the newly created, parsed JSON. See below from logstash.conf:
filter {
mutate {
remove_field => [ "message", "@version", "headers"]
}Found the source of the bug. The function I was passing to userale.map had an edge case where there was no return so a handful of logs got swallowed by that but still passed along to logstash as nulls >.<
EandrewJones
commented
1 year ago Thanks. I think I've traced it down to sendOnInterval, at least in the example page.
Work flow: hit submit > sendOnClose triggered > page reloads > sendOnInterval triggered > empty line appears in json log + page load log.
Best
Evan Jones 郑恩尉 Ph.D Student in Government and Politics University of Maryland--College Park
Website: www.ea-jones.com
On Thu, Apr 21, 2022 at 4:40 PM UncleGedd @.***> wrote:
Hi @EandrewJones https://github.com/EandrewJones ! Thanks for raising the issue, will take a look tomorrow
— Reply to this email directly, view it on GitHub https://github.com/apache/incubator-flagon-useralejs/issues/243#issuecomment-1105737067, or unsubscribe https://github.com/notifications/unsubscribe-auth/AJ2T6ANTYUYSS3QVHQCDWTTVGG4KLANCNFSM5UAIDWTA . You are receiving this because you were mentioned.Message ID: @.***>
Userale is injecting nulls into the log arrays it sends to the source destination. This is breaking the logstash parser that routes them to elasticsearch.
For example, see the end of this array:
These empty entries also appear in the local .json file logs generated from the example page:
In particular, the submit button always generates a empty line. However, it's not isolated to click events because I'm encountering this issue for mouseover events and custom logs.
I haven't been able to track down the source. I tried modifying userale source code to console.log the log arrays before
sendLogssends them to the backend, but I didn't find nulls in those.