A message field has invalid type
metanovii opened this issue · 17 comments
tlog-play -r es --es-baseurl=http://127.0.0.1:9200/tlog-2019.07.12/_search --es-query='session:369495'
A message field has invalid type
Failed reading the source at message #0
Version elasticsearch 7.. , tlog v6
Hello @metanovii
Could you please provide the JSON entry for this recording in elasticsearch, specifically the message field. I believe this can be done with curl or another utility.
Thank you.
Hello @metanovii
Could you please provide the JSON entry for this recording in elasticsearch, specifically the message field. I believe this can be done with curl or another utility.
Thank you.
{
"_index": "tlog-2019.07.12",
"_type": "_doc",
"_id": "TCWC5msB_kfsYGi5qP2d",
"_version": 1,
"_score": null,
"_source": {
"rec": "2fd5733ebbc2491dbb00ed9f7b2fa573-106d-13725b3f4",
"timing": "<1+2872<1+600<1+39<1+39<1+40<1+40<1+39<1+40<1+40<1+40<1",
"id": 9,
"out_txt": "",
"beat": {
"hostname": "my",
"name": "my",
"version": "6.3.2"
},
"timestamp": "2019-07-12T17:07:03.443709+03:00",
"tags": [
"tlog",
"beats_input_raw_event"
],
"in_txt": "\r\r\r\r\r\r\r\r\r\r\r",
"ver": "2.2",
"user": "s.mikhaltsov",
"in_bin": [],
"source": "/var/log/tlog.log",
"session": 369495,
"offset": 139506294,
"term": "xterm-256color",
"@version": "1",
"host": {
"name": "my"
},
"pos": 163414,
"@timestamp": "2019-07-12T14:07:10.667Z",
"out_bin": []
},
"fields": {
"@timestamp": [
"2019-07-12T14:07:10.667Z"
],
"timestamp": [
"2019-07-12T14:07:03.443Z"
]
},
"highlight": {
"user.keyword": [
"@kibana-highlighted-field@s.mikhaltsov@/kibana-highlighted-field@"
]
},
"sort": [
1562940430667
]
}It looks like the problem is with the host field:
"host": {
"name": "my"
},
Tlog is checking that this host value is a JSON string type but it is an array object in this entry.
Removing elasticsearch from the equation, I see the same problem if I manually change the host value with a basic file writer playback test:
$ tlog-rec -o testing ls
$ vim testing
"host":{"my":"hostname"}
$ tlog-play -i testing
A message field has invalid type
Failed reading the source at line 1
Do you see this issue on other tlog recordings stored in your elastic search database? Could it be this field is modified by some other non-tlog application ?
I understood. I fixed my configuration for logstash and now i have json :
{
"_index": "tlog-2019.07.13",
"_type": "_doc",
"_id": "cLHo62sB_kfsYGi5lWpz",
"_version": 1,
"_score": null,
"_source": {
"source": "/var/log/tlog.log",
"user": "s.mikhaltsov",
"id": 7,
"timestamp": "2019-07-13T18:16:44.411584+03:00",
"offset": 139510401,
"tags": [
"tlog",
"beats_input_codec_plain_applied"
],
"ver": "2.2",
"in_txt": "d�aaaaaaaaaaaaaaaaaaaaaa\r",
"session": 369986,
"out_bin": [],
"term": "xterm-256color",
"pos": 2104666,
"@version": "1",
"timing": "<1+711<1+34<1+605<1+44<1+30<1+49<1+43<1+39<1+36<1+44<1+47<1+31<1+36<1+43<1+48<1+35<1+35<1+40<1+43<1+40<1+39<1+40<1+39<1+159<1",
"host": "my",
"rec": "2fd5733ebbc2491dbb00ed9f7b2fa573-2244-137acf474",
"in_bin": [],
"out_txt": "",
"@timestamp": "2019-07-13T15:16:53.202Z"
},
"fields": {
"@timestamp": [
"2019-07-13T15:16:53.202Z"
],
"timestamp": [
"2019-07-13T15:16:44.411Z"
]
},
"sort": [
1563031013202
]
}I think it should be work. I think I can verify this on Monday.
Can i make MR for readme about configuration filebeat+logstash ?
Now that work without error, but response empty :D
metanovii nix-pc-10 master ?
$ tlog-play -r es --es-baseurl=http://127.0.0.1:9200/tlog-2019.07.15/_search --es-query='session:370770'But i have reccords in ES for that session:
{
"_index": "tlog-2019.07.15",
"_type": "_doc",
"_id": "aZGi9GsB_kfsYGi5ksQe",
"_version": 1,
"_score": null,
"_source": {
"source": "/var/log/tlog.log",
"user": "s.mikhaltsov",
"id": 3,
"timestamp": "2019-07-15T10:56:56.637802+03:00",
"offset": 895,
"tags": [
"tlog",
"beats_input_codec_plain_applied"
],
"ver": "2.2",
"in_txt": "dddddddddddddddd\r",
"session": 370770,
"out_bin": [],
"term": "xterm-256color",
"pos": 1912670,
"@version": "1",
"timing": "<1+364<1+39<1+39<1+40<1+39<1+40<1+39<1+40<1+40<1+39<1+39<1+40<1+40<1+44<1+36<1+112<1",
"host": "my",
"rec": "2fd5733ebbc2491dbb00ed9f7b2fa573-7848-1388ca81a",
"in_bin": [],
"out_txt": "",
"@timestamp": "2019-07-15T07:56:59.214Z"
},
"fields": {
"@timestamp": [
"2019-07-15T07:56:59.214Z"
],
"timestamp": [
"2019-07-15T07:56:56.637Z"
]
},
"sort": [
1563177419214
]
}Here we see:
"in_txt": "dddddddddddddddd\r",
"out_txt": "",
It looks like there is a tlog-play issue playing back recorded input when output logging is disabled. This can be reproduced with:
$ tlog-rec -o testing --log-input=True --log-output=False
@spbnick Do you know if this behavior intended by design or should it be fixed? I did not see it documented anywhere.
@metanovii If you can test with a recording that includes logged output, I would expect it will work.
-Justin
@justin-stephenson, what exact issue do you mean? tlog-play doesn't play back input, and if there's no recorded output, it won't play anything.
@spbnick My mistake, I did not know that tlog-play does not play back input.
@metanovii Is the problem clear now? There needs to be some output for tlog-play to playback.
@justin-stephenson yep, with output tlog-play work, but some time i have message :D :
Message ID is out of order
Failed reading the source at message #1@metanovii, what's your Elasticsearch query string? Are you sure it's not returning more than one recording?
@metanovii, regarding the MR, absolutely! Please do create the MR and we'll work with you to have it integrated one way or another.
@spbnick
tlog-rec-sesssion config:
{
"shell" : "/bin/bash",
"notice" : "\n kuku :) \n\n",
"latency" : 10,
"payload" : 16384,
"log": {
"input" : true,
"output" : true,
"window" : false
},
"limit": {
"rate" : 32768,
"burst" : 32768,
},
"syslog": {
"facility" : "user",
"priority" : "info"
},
"writer" : "syslog"
}1 log record:
{
"_index": "tlog-2019.07.16",
"_type": "_doc",
"_id": "T421-WsB_kfsYGi5AWiC",
"_version": 1,
"_score": null,
"_source": {
"source": "/var/log/tlog.log",
"user": "s.mikhaltsov",
"id": 1,
"timestamp": "2019-07-16T10:35:11.043978+03:00",
"offset": 72404,
"out_bin": [],
"session": 371382,
"pos": 0,
"@version": "1",
"timing": ">96+4240<1>1+559<1>2+1>125",
"rec": "2fd5733ebbc2491dbb00ed9f7b2fa573-3d7a-139116b75",
"out_txt": "\u001b]0;s.mikhaltsov@my: ~\u0007\u001b[01;32ms.mikhaltsov@my\u001b[00m:\u001b[01;34m~\u001b[00m$ 1\r\n-bash: 1: command not found\r\n\u001b]0;s.mikhaltsov@my: ~\u0007\u001b[01;32ms.mikhaltsov@my\u001b[00m:\u001b[01;34m~\u001b[00m$ ",
"in_txt": "1\r",
"ver": "2.2",
"tags": [
"tlog",
"beats_input_codec_plain_applied"
],
"term": "xterm-256color",
"input": {
"type": "log"
},
"host": "my",
"in_bin": [],
"prospector": {
"type": "log"
},
"@timestamp": "2019-07-16T07:35:15.199Z"
},
"fields": {
"@timestamp": [
"2019-07-16T07:35:15.199Z"
],
"timestamp": [
"2019-07-16T07:35:11.043Z"
]
},
"sort": [
1563262515199
]
}2 log record:
{
"_index": "tlog-2019.07.16",
"_type": "_doc",
"_id": "6Y21-WsB_kfsYGi5NnLr",
"_version": 1,
"_score": null,
"_source": {
"source": "/var/log/tlog.log",
"user": "s.mikhaltsov",
"id": 2,
"timestamp": "2019-07-16T10:35:22.323761+03:00",
"offset": 73004,
"tags": [
"tlog",
"beats_input_codec_plain_applied"
],
"ver": "2.2",
"in_txt": "2\r3\r4",
"session": 371382,
"out_bin": [],
"term": "xterm-256color",
"pos": 11280,
"@version": "1",
"timing": "<1>1+303<1>2+1>125+6997<1>1+351<1>2+1>29+1>96+2189<1>1",
"host": "my",
"rec": "2fd5733ebbc2491dbb00ed9f7b2fa573-3d7a-139116b75",
"in_bin": [],
"out_txt": "2\r\n-bash: 2: command not found\r\n\u001b]0;s.mikhaltsov@my: ~\u0007\u001b[01;32ms.mikhaltsov@my\u001b[00m:\u001b[01;34m~\u001b[00m$ 3\r\n-bash: 3: command not found\r\n\u001b]0;s.mikhaltsov@my: ~\u0007\u001b[01;32ms.mikhaltsov@my\u001b[00m:\u001b[01;34m~\u001b[00m$ 4",
"@timestamp": "2019-07-16T07:35:30.200Z"
},
"fields": {
"@timestamp": [
"2019-07-16T07:35:30.200Z"
],
"timestamp": [
"2019-07-16T07:35:22.323Z"
]
},
"sort": [
1563262530200
]When i try play logs:
$ tlog-play -r es -f --es-baseurl=http://127.0.0.1:9200/tlog-2019.07.16/_search --es-query='session:371382'
s.mikhaltsov@my:~$ 1
-bash: 1: command not found
s.mikhaltsov@my:~$
Message ID is out of order
Failed reading the source at message #1
:(
Thank you, @metanovii. Could you try running this command to see what exactly Elasticsearch returns to tlog:
curl 'http://127.0.0.1:9200/tlog-2019.07.16/_search?q=session:371382&sort=id:asc'
Or just capture the traffic to Elasticsearch with e.g. Wireshark and post here?
$ curl -q 'http://127.0.0.1:9200/tlog-2019.07.16/_search?q=session:371382&sort=id:asc' | jq
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 16857 100 16857 0 0 152k 0 --:--:-- --:--:-- --:--:-- 151k
{
"took": 5,
"timed_out": false,
"_shards": {
"total": 1,
"successful": 1,
"skipped": 0,
"failed": 0
},
"hits": {
"total": {
"value": 8,
"relation": "eq"
},
"max_score": null,
"hits": [
{
"_index": "tlog-2019.07.16",
"_type": "_doc",
"_id": "T421-WsB_kfsYGi5AWiC",
"_score": null,
"_source": {
"source": "/var/log/tlog.log",
"user": "s.mikhaltsov",
"id": 1,
"timestamp": "2019-07-16T10:35:11.043978+03:00",
"offset": 72404,
"out_bin": [],
"session": 371382,
"pos": 0,
"@version": "1",
"timing": ">96+4240<1>1+559<1>2+1>125",
"rec": "2fd5733ebbc2491dbb00ed9f7b2fa573-3d7a-139116b75",
"out_txt": "\u001b]0;s.mikhaltsov@my-leadgid-space: ~\u0007\u001b[01;32ms.mikhaltsov@my-leadgid-space\u001b[00m:\u001b[01;34m~\u001b[00m$ 1\r\n-bash: 1: command not found\r\n\u001b]0;s.mikhaltsov@my-leadgid-space: ~\u0007\u001b[01;32ms.mikhaltsov@my-leadgid-space\u001b[00m:\u001b[01;34m~\u001b[00m$ ",
"in_txt": "1\r",
"ver": "2.2",
"tags": [
"tlog",
"beats_input_codec_plain_applied"
],
"term": "xterm-256color",
"input": {
"type": "log"
},
"host": "my-leadgid-space",
"in_bin": [],
"prospector": {
"type": "log"
},
"@timestamp": "2019-07-16T07:35:15.199Z"
},
"sort": [
1
]
},
{
"_index": "tlog-2019.07.16",
"_type": "_doc",
"_id": "UI21-WsB_kfsYGi5AWiC",
"_score": null,
"_source": {
"source": "/var/log/tlog.log",
"user": "s.mikhaltsov",
"id": 1,
"timestamp": "2019-07-16T10:35:11.043978+03:00",
"offset": 72404,
"tags": [
"tlog",
"beats_input_codec_plain_applied"
],
"ver": "2.2",
"in_txt": "1\r",
"session": 371382,
"out_bin": [],
"term": "xterm-256color",
"pos": 0,
"@version": "1",
"timing": ">96+4240<1>1+559<1>2+1>125",
"host": "my-leadgid-space",
"rec": "2fd5733ebbc2491dbb00ed9f7b2fa573-3d7a-139116b75",
"in_bin": [],
"out_txt": "\u001b]0;s.mikhaltsov@my-leadgid-space: ~\u0007\u001b[01;32ms.mikhaltsov@my-leadgid-space\u001b[00m:\u001b[01;34m~\u001b[00m$ 1\r\n-bash: 1: command not found\r\n\u001b]0;s.mikhaltsov@my-leadgid-space: ~\u0007\u001b[01;32ms.mikhaltsov@my-leadgid-space\u001b[00m:\u001b[01;34m~\u001b[00m$ ",
"@timestamp": "2019-07-16T07:35:15.199Z"
},
"sort": [
1
]
},
{
"_index": "tlog-2019.07.16",
"_type": "_doc",
"_id": "6Y21-WsB_kfsYGi5NnLr",
"_score": null,
"_source": {
"source": "/var/log/tlog.log",
"user": "s.mikhaltsov",
"id": 2,
"timestamp": "2019-07-16T10:35:22.323761+03:00",
"offset": 73004,
"tags": [
"tlog",
"beats_input_codec_plain_applied"
],
"ver": "2.2",
"in_txt": "2\r3\r4",
"session": 371382,
"out_bin": [],
"term": "xterm-256color",
"pos": 11280,
"@version": "1",
"timing": "<1>1+303<1>2+1>125+6997<1>1+351<1>2+1>29+1>96+2189<1>1",
"host": "my-leadgid-space",
"rec": "2fd5733ebbc2491dbb00ed9f7b2fa573-3d7a-139116b75",
"in_bin": [],
"out_txt": "2\r\n-bash: 2: command not found\r\n\u001b]0;s.mikhaltsov@my-leadgid-space: ~\u0007\u001b[01;32ms.mikhaltsov@my-leadgid-space\u001b[00m:\u001b[01;34m~\u001b[00m$ 3\r\n-bash: 3: command not found\r\n\u001b]0;s.mikhaltsov@my-leadgid-space: ~\u0007\u001b[01;32ms.mikhaltsov@my-leadgid-space\u001b[00m:\u001b[01;34m~\u001b[00m$ 4",
"@timestamp": "2019-07-16T07:35:30.200Z"
},
"sort": [
2
]
},
{
"_index": "tlog-2019.07.16",
"_type": "_doc",
"_id": "6I21-WsB_kfsYGi5NnLq",
"_score": null,
"_source": {
"source": "/var/log/tlog.log",
"user": "s.mikhaltsov",
"id": 2,
"timestamp": "2019-07-16T10:35:22.323761+03:00",
"offset": 73004,
"out_bin": [],
"session": 371382,
"pos": 11280,
"@version": "1",
"timing": "<1>1+303<1>2+1>125+6997<1>1+351<1>2+1>29+1>96+2189<1>1",
"rec": "2fd5733ebbc2491dbb00ed9f7b2fa573-3d7a-139116b75",
"out_txt": "2\r\n-bash: 2: command not found\r\n\u001b]0;s.mikhaltsov@my-leadgid-space: ~\u0007\u001b[01;32ms.mikhaltsov@my-leadgid-space\u001b[00m:\u001b[01;34m~\u001b[00m$ 3\r\n-bash: 3: command not found\r\n\u001b]0;s.mikhaltsov@my-leadgid-space: ~\u0007\u001b[01;32ms.mikhaltsov@my-leadgid-space\u001b[00m:\u001b[01;34m~\u001b[00m$ 4",
"in_txt": "2\r3\r4",
"ver": "2.2",
"tags": [
"tlog",
"beats_input_codec_plain_applied"
],
"term": "xterm-256color",
"input": {
"type": "log"
},
"host": "my-leadgid-space",
"in_bin": [],
"prospector": {
"type": "log"
},
"@timestamp": "2019-07-16T07:35:30.200Z"
},
"sort": [
2
]
},I see that your query returns each message twice. Tlog can't handle that. You'll need to either make sure only one message is logged to Elasticsearch, or filter one of each message out in the query.
Closing as this appears to be resolved, please re-open if needed.