COVESA/dlt-daemon

Logstorage control: Message failed to be send. Please check DLT config.

CodeTornato opened this issue · 11 comments

hello again,dear dlt team,
my dlt-daemon version is 2.18.7, I was following dlt offline logstorage tutorial in order to save my log message to the file system.
when I execute dlt-logstorage-ctrl -c 1 -p ~/workspace/dlt_test(cuz dlt_logstorage.conf file is here),I got this error output:
image
but when I execute dlt-example-user hello123, a log message file was successfully created:
image

so I checked the source code, I am seeing message failed to be send, because in dlt-control.c, there is dlt_logstorage_ctrl_single_request() function, finally dlt_control_send_message() in dlt-control-common.c got called,
image
there is comment said "at this point either value is already correcte,either it's still -1",but from callback_return being set -1 to return callback_return, I didnt find anywhere to set callack_return to other value, is this an issue, or I'm missing somewhere?
and if it were really was failing to send message to dlt, dlt log message should'nt be generated in my directrory,right?

@CodeTornato My hypothesis would be that the callback_return is set on purpose to catch a value, and then returns it if it is changed at some point after, and if callback_return is still the same, it returns -1, However, I do think that should be structured differently as it could lead to more problems.

You raise a valid point that it does not seem to be changed from any internal or external factors. I have not seen any other occurrences of callback_return being altered within the file. I'll investigate further on this issue.

@CodeTornato callback_return is a static variable (global), so its value changes throughout the duration of runtime. Looking up in the dlt_control_callback function, you can find callback_return being altered using response_analyzer_cb. This changes the value of callback_analyzer to whatever the program expects. This may occur many more times throughout dlt-common-control.c, but I believe it has some influence in callback_return's value.

callback_return = response_analyzer_cb(text, message->databuffer, (int) message->datasize);

However, in dlt_control_send_message, callback_return is re-init to -1, but the function expects a return from the response analyzer, so unless I am missing something too, it would not make sense to remove the value before returning.

@LukeTheEngineer thank you so much for your insight, indeed in dlt_control_caback() function callback_return is being updated with response_analyzer_cb(), and I wanted to make sure this line of code is being executed by adding bit printing:
image
and thats how I traced the value of callback_return, but this time I didnt see my printf message in console when I execute dlt-logstorage-ctrl. so this mean that dlt_control_callback() function was not executed in my case,is this function suppose to executed everytime?

@CodeTornato I'm not sure. I am still pretty new to contributing to the repo, but I can say that it does play a significant part in the callback_return, so it is likely that the function is supposed to be invoked everytime.

If it is not invasive, could you please provide you command arguments and/or more details on your calling methods? Some more context would be great.

@LukeTheEngineer yeah sure,
first step was running the dlt-daemon with dlt.conf, here is the dlt.conf I used
dlt.zip
and open second terminal run the second command:
dlt-logstorage-ctrl -c 1 -p ~/workspace/dlt_test
in dlt_test directory there is a dlt_logstorage_file:
dlt_logstorage.zip
with this command I got "message fail to be send error", but like I said after openning thrid terminal and run the example program at build/src/example:
dlt-example-user hello123
a dlt.log file was generated as I wanted, I dont know if I am suppose to ignore this error message since the log file is generated at ~/workspace/dlt_test.
and more for detail here is the output after I run dlt-daemon in first step with verbose mode
dlt_daemon.log.zip
and also the verbose output after dlt-logstorage-ctrl command in the second step:
log_storage_ctrl_output.zip

Hello @CodeTornato , @LukeTheEngineer ,
thanks for your interest in DLT topic.

I could see that this was a known issue, so let me check for the root cause by using your configuration.
I will update soon.

Regards

@LukeTheEngineer @minminlittleshrimp
thank you so much! I'm very much looking forward to your update!

Hello @CodeTornato
It seems after entering the client main loop, some issues happen there, I could not show a full RCA here since I have not done my analysis yet.
This issue has already been fix for current release, could you try with later version?
Regards

Indeed, I was using DLT v2.18.7. I have now tried with both DLT v2.18.8 and v2.18.9, and the error message has disappeared. Thank you all so much once again.

Great work.

Hello @LukeTheEngineer @CodeTornato
So sorry for my late updating with you guys my RCA.
In case you are interested in finding the true root cause of this issue, I think my RCA will satisfy you 😉

RCA:

Root cause: Verbose mode needs messages sent with Serial header
Solution for version <= 2.18.7:
Enable manually this feature by SendSerialHeader = 1 in dlt.conf whenever Verbose mode is used
For > v2.18.7:
It is an option for enabling/disabling sending serial header -> no fail issue when parsing argument from dlt.conf

$ dlt-logstorage-ctrl -h
Usage: dlt-logstorage-ctrl [options]
Send a trigger to DLT daemon to connect/disconnecta certain logstorage device

Options:
  -c --command               Connection type: connect = 1, disconnect = 0
  -d[prop] --daemonize=prop  Run as daemon: prop = use proprietary handler
                             'prop' may be replaced by any meaningful word
                             If prop is not specified, udev will be used
  -e --ecuid                 Set ECU ID (Default: ECU1)
  -h --help                  Usage
  -p --path                  Mount point path
  -s[path] --snapshot=path   Sync Logstorage cache
                             Don't use -s together with -d and -c
  -t                         Specify connection timeout (Default: 10s)
  -S --send-header           Send message with serial header (Default: Without serial header)
  -R --resync-header         Enable resync serial header
  -v --verbose               Set verbose flag (Default:0)

Commit from which git bisect points out that this issue is fixed by a new feature: 0ee7fdf
Link to Upstream PR including this feature: #331
Code line which disables option serial header implicitly so that no fail when reading message in client main loop:

set_send_serial_header(0);

Testing on local machine:
Env: Ubuntu 18
Ver.: v.2.18.7
Setup config:

Verbose = 1
SendSerialHeader = 1

Run logstorage control to mount the mountpoint:

$ dlt-logstorage-ctrl -c 1 -p <PATH> -v
Logstorage control: Now in verbose mode.
Logstorage control: One shot.
Logstorage common: Now scanning <PATH>
Logstorage common: Checking ..
Logstorage common: Checking ...
Logstorage common: Checking .gdb_history.
Logstorage common: Checking dlt_logstorage.conf.
Logstorage common: File found.
Common control: Initializing the connection.
[ 8424.398376]~DLT~30974~INFO     ~dlt_client_init: Init dlt client struct with default port: 3490.
Logstorage control: event type is [1]	 device path is [<PATH>]
Logstorage common: Sending event 1 for <PATH>
Logstorage common: Body is now ready.
Common control: Preparing message.
[ 8424.398450]~DLT~30974~INFO     ~dlt_message_init()
Common control: Preparing headers.
Common control: Preparing extra headers.
[ 8424.398456]~DLT~30974~INFO     ~dlt_message_set_extraparameters()
Common control: Ready to receive DLT answers.
[ 8424.398562]~DLT~30974~INFO     ~dlt_message_init()
[ 8424.398573]~DLT~30974~INFO     ~dlt_message_read()  [--------------> READ HEADER SUCCESSFULLY]
[ 8424.398575]~DLT~30974~INFO     ~dlt_message_get_extraparameters()
[ 8424.398597]~DLT~30974~INFO     ~dlt_message_header_flags()
[ 8424.398630]~DLT~30974~INFO     ~dlt_message_payload()
Logstorage control: Response received: 'service(3845), ok'
Logstorage control: Response expected: 'service(3845), ok'
[ 8424.398640]~DLT~30974~INFO     ~dlt_message_read()
[ 8424.398695]~DLT~30974~INFO     ~dlt_message_free()
[ 8424.398770]~DLT~30974~INFO     ~dlt_client_cleanup: Cleanup dlt client
Logstorage control: Exiting.

Above is my full analysis on this issue.
Please kindly give your comment if you find it interesting 😎
Hello @michael-methner, FYI
DLT team