Error messages are not shown if motmod is loaded and not started

[hdiethelm]

In 2.9, the message is:

hm2: loading Mesa HostMot2 driver version 0.15
Unknown parameter `num_pwmgens=1'
./hm2-stepper-eth.hal:38: waitpid failed /home/hannes/linuxcnc-src/bin/rtapi_app hm2_eth
./hm2-stepper-eth.hal:38: /home/hannes/linuxcnc-src/bin/rtapi_app exited without becoming ready
./hm2-stepper-eth.hal:38: insmod for hm2_eth failed, returned -1

In master, the message is:

hm2: loading Mesa HostMot2 driver version 0.15
./hm2-stepper-eth.hal:38: waitpid failed /home/hannes/linuxcnc-src/bin/rtapi_app hm2_eth
./hm2-stepper-eth.hal:38: /home/hannes/linuxcnc-src/bin/rtapi_app exited without becoming ready
./hm2-stepper-eth.hal:38: insmod for hm2_eth failed, returned -1

Note the missing Unknown parameter 'num_pwmgens=1'. This message is not printed any more which probably would have saved me 90% of the time debugging the issue #3946.

The issue is introduced with this commit: 47324a7

In motion.c after init, all messages are routed through emc_message_handler. https://github.com/LinuxCNC/linuxcnc/blob/master/src/emc/motion/motion.c#L415

So in the case loading future modules fails and the error is for example printed in https://github.com/LinuxCNC/linuxcnc/blob/master/src/rtapi/uspace_rtapi_app.cc#L232, this is never shown due to the motion thread never starts.

Options:

• Only switch the message handler to emc_message_handler when motion is started
• Revert the commit and accept that there are duplicated messages
• ...probably more

[BsAtHome]

This is probably the same bug that caused the long search in #3822 its workaround fix in #3824.

I'd rather see duplicate messages instead of non at all... But what is the actual root-cause of duplicate messages?

BTW, is it possible to switch the emc_message_handler in the startup procedure of the motion thread, as last action when all went fine?

[hdiethelm]

Yes, this is most probably the root cause in #3822. After this is corrected, #3824 can be reverted.

47324a7 was right in that there are two paths as soon as emc_message_handler() is active, both are rather long:

rtapi_print_msg() -> *rtapi_msg_handler() -> emc_message_handler() ->  
  1-> emcmotErrorPutfv() -> fifo -> read by motion task in emctaskmain.cc -> emcMotionUpdate() -> if(usrmotReadEmcmotError()){ emcOperatorError() } -> rcs_print() -> stdout
  2-> *old_handler() -> default_rtapi_msg_handler() -> fifo -> read by task in uspace_rtapi_app.cc:queue_function() -> stdout

2.9 has also the duplicated error message issue, so bisecting probably doesn't help here.

As far as I understand it reading the code, emc_message_handler() is used to forward the messages to the gui, right? So one option would be to not do rcs_print to stdout and leave old_handler() in as it was before.

Triggering error message is not that simple. Or is there something do that? Otherwise, a simple hal module to generate error messages would be helpful to test all this paths. You could generate error messages based on a few signals, so you can easily test this.

[hdiethelm]

BTW, is it possible to switch the emc_message_handler in the startup procedure of the motion thread, as last action when all went fine?

Possible yes. But there is still the chance that the motion task crashes and you don't see why because that exact error message is never shown. Not shown error messages is always pretty annoying.

Hmm, looking at: emc_message_handler(), is there any thread safety in this fifo? This num++ / num-- in emcmotErrorPutfv() / emcmotErrorGet() looks like a possible race condition.

[BsAtHome]

There is one reader and one writer on a fixed size buffer queue. It looks like it is more a question of atomicity and reordering and that is not guaranteed.

[BsAtHome]

Triggering error message is not that simple. Or is there something do that? Otherwise, a simple hal module to generate error messages would be helpful to test all this paths. You could generate error messages based on a few signals, so you can easily test this.

Something like the following code (untested). Should expose four bit input pins. Low-to-high transition pushes out a message.

component pushmsg "Push a message to non-RT";
pin in bit debug "Generate a debug message";
pin in bit info "Generate an info message";
pin in bit warning "Generate a warning message";
pin in bit error "Generate an error message";

description """
Generate fixed messages from realtime to non-realtime for debug purposes.
"""
;
option period no;
function _;
license "GPL";
author "LinuxCNC";

variable bool sd;
variable bool si;
variable bool sw;
variable bool se;
variable signed n;
;;
FUNCTION(_)
{
    bool newsd = debug;
    if(newsd && !sd)
        rtapi_print_msg(RTAPI_MSG_DBG, "Debug message %d\n", n++);
    sd = newsd;

    bool newsi = info;
    if(newsi && !si)
        rtapi_print_msg(RTAPI_MSG_INFO, "Info message %d\n", n++);
    si = newsi;

    bool newsw = warning;
    if(newsw && !sw)
        rtapi_print_msg(RTAPI_MSG_WARN, "Warning message %d\n", n++);
    sw = newsw;

    bool newse = error;
    if(newse && !se)
        rtapi_print_msg(RTAPI_MSG_ERR, "Error message %d\n", n++);
    se = newse;
}

[hdiethelm]

There is one reader and one writer on a fixed size buffer queue. It looks like it is more a question of atomicity and reordering and that is not guaranteed.

There can be as many writers as there are threads calling rtapi_print_msg() concurrently. I did not see any mechanism avoiding this. uspace_rtapi_app.cc uses boost::lockfree::queue to guarantee thread safety but in emc_message_handler() i did not find anything. Anyway, this is unrelated to the actual problem and mostly a theoretical issue due to normally there are not so many error messages generated in parallel. Ok if I just create a new issue?

Something like the following code (untested). Should expose four bit input pins. Low-to-high transition pushes out a message.

Thanks for the code, that will help a lot. It should go to master as soon as it is tested and if possible even integrated in some automatic test.

Someone willing to fix this issue? I have other PR's open and new ones in the pipeline and I also need some quality time at my CNC... ;-)

[BsAtHome]

Ok if I just create a new issue?

Sure.

[hdiethelm]

Done: #3951