[grandixximo]

Fixes #4689. @BsAtHome, this is your idea of fixing it where the message is printed, extended to every level. @hdiethelm, thanks for the report and for pushing it this way.

Every rtapi_print_msg() message is a line of its own:

• The default message handlers add the newline when the text lacks one, at every level: in uspace in the main thread of rtapi_app, in the queue that prints the messages of its realtime threads and in user processes, and in RTAI in the kernel handler and in user space. rtapi_print() still prints like printf. A format that already ends in a newline prints as before, so the existing formats and their translations do not change, and new code may leave the newline out.
• The places that built one line from several calls print it with one: motion's command debug output, rtapi_app's isolated cpuset report, the PPMC slot scan, halcmd's command echo and the hm2_modbus frame dumps, which now print one message for every 16 bytes from a small buffer, so the stack of the realtime thread does not grow. A line built in parts is a set of separate messages, and anything printed between them lands in the middle of the line.
• Task drops the newline at the end of an operator error, so the GUIs no longer show it as a blank line or, in Touchy, as a ↵ glyph. Motion's reportError() adds its console newline only when the text lacks one.
• The RTAI kernel handler gives rt_printk() the text as an argument instead of as the format.

tests/rtapi-msg-newline prints errors, a warning and an info message without a newline from the main thread of rtapi_app and from a realtime thread, an error with its newline, and an rtapi_print() line in two parts. I also checked the errors Touchy shows, from a test component and from task and motion, on master and with this PR: the only difference is the glyph at the end. The full suite passes apart from blendmath, which does not build with GCC 14 (#4676). I cannot build RTAI here.

[hdiethelm]

It is probably a good thing to enforce a newline but it can have side effects.

A few things to consider:

linuxcnc/src/emc/motion/homing.c

Line 282 in eab7726

rtapi_print_msg(RTAPI_MSG_ERR,_("j%d end of move in home state %d"),jno, H[jno].home_state);

The _( including #define _(s) (s) can probably be removed as long as homing.c is only used in realtime context.

There are some places like this:

linuxcnc/src/emc/motion/command.c

Line 2136 in b99baf8

rtapi_print_msg(RTAPI_MSG_DBG, "\n");

or

linuxcnc/src/rtapi/uspace_rtapi_app.cc

Line 252 in b99baf8

rtapi_print_msg(RTAPI_MSG_INFO, "\n");

This cases will now produce to many newlines or clobbered messages.

As soon as motion is running, messages go trough a different path:

linuxcnc/src/emc/motion/motion.c

Line 460 in b99baf8

rtapi_set_msg_handler(emc_message_handler);

linuxcnc/src/emc/motion/motion.c

Line 247 in b99baf8

static void emc_message_handler(msg_level_t level, const char *fmt, va_list ap)

As much as I remember, this path to the gui goes to translation and adds a newline always. That's why the GUI pop-up's often have a newline to much. But a lot was changed since I touched it in #4116.

[grandixximo]

@hdiethelm thanks for looking. In order:

• In realtime _() is a no-op, but motion passes the format and its arguments through the error buffer, and snprintdbuf() in usrmotintf.cc translates the format for the GUI. The marker is what puts the strings into the .po files, so I would keep it.
• command.c:2136 and uspace_rtapi_app.cc:252 are debug and info messages built in parts. This PR leaves those levels alone; only errors and warnings get the newline, so their output does not change. tests/rtapi-msg-newline checks that an info line printed in two parts stays one line.
• Once motmod is loaded, emc_message_handler() sends errors to the GUI through emcmotErrorPutfv() and every message to old_handler, which is the default handler this PR changes. So the console gets the newline and the path to the GUI is unchanged. reportError() already adds a newline for the console, so its messages do not change either.

[grandixximo]

@hdiethelm, does the reply above settle your points? If so, I would merge this.

[hdiethelm]

I need to think a bit more about this. Adding only newlines if missing and only if error or warning is not consistent and will make future bugs more likely.

One might set an info message to error temporarely to test something and then wonders why it behaves differently. Then he will fix it not realizing that this is now wrong for info.

Also errors go to the GUI where a newline is added unconditionally as much as I remember.

So it would be better to add a newline always and fix all the messages. But this is a lot of change.

Or just leave it for now, there are discussions going on about a logging system, and continue as soon they have setteled.

[hdiethelm]

So, I was able to verify my suspicion:
In the GUI, a newline is added unconditionally. The following code:

    rtapi_print_msg(RTAPI_MSG_ERR, "msgline: error at load1\n  test1");
    rtapi_print_msg(RTAPI_MSG_ERR, "msgline: error at load2\n  test2\n");
    rtapi_print_msg(RTAPI_MSG_ERR, "msgline: error at load3\n  test3");

results in:

Checking other places for logs, it's a mixed bag:
emcOperatorError(_("can't do that (%s:%d) in manual mode"), emc_symbol_lookup(type),(int) type);
rcs_print_error("hal_init error\n"); or after #4627 log_error("hal_init error\n");
Probably a bug: log_error("fwrite({}) error: {}", remote_tmpfilename, strerror(errno));
Python: LOG.debug("Button {0} has been pressed".format(button[1]))

What I would suggest:
rtapi_print_msg() / log_error() and any other logging functionality: Never use a trailing newline in code, unconditionally append it if needed in output stage. This is what most loggers do. And it has the advantage that you can add text on the same line if needed inside the logging facility.

rtapi_print(): Should behave like printf, no newline change.

Now this would be quite a change to remove several 1000's of trailing newlines in code. However, it would clear the way to use a logging library and make things consistent.

The few places where one message is created using multiple rtapi_print_msg() should just be fixed. The one in rtapi_app is my fault, sorry.

@BsAtHome Some input from your side?

[hdiethelm]

Just a quick&dirty spdlog prototype: https://github.com/hdiethelm/linuxcnc-fork/tree/spdlog_prototype
With this, all trailing newlines create issues besides the often used rtapi_print_msg(RTAPI_MSG_ERR, "Note: ..."); pattern.

LINUXCNC - 2.10.0~pre2
Machine configuration directory is '/home/hannes/linuxcnc-src/configs/sim/axis'
Machine configuration file is 'axis_mm.ini'
Starting LinuxCNC...
[2026-10-19 23:05:03.164] [error] Note: realtime scheduling unavailable (sched_setscheduler SCHED_FIFO: Operation not permitted).
  Process capabilities: cap_sys_nice=no cap_ipc_lock=no.
  Falling back to POSIX non-realtime.
  Fix: 'sudo make setcap' (preferred) or 'sudo make setuid' on rtapi_app.
  Override (testing only): set LINUXCNC_FORCE_REALTIME=1.

[2026-10-19 23:05:03.165] [error] Note: Using POSIX non-realtime

linuxcnc TPMOD=tpmod HOMEMOD=homemod EMCMOT=motmod
Found file(lib): /home/hannes/linuxcnc-src/lib/hallib/core_sim.hal
Found file(lib): /home/hannes/linuxcnc-src/lib/hallib/sim_spindle_encoder.hal
Found file(lib): /home/hannes/linuxcnc-src/lib/hallib/axis_manualtoolchange.hal
Found file(lib): /home/hannes/linuxcnc-src/lib/hallib/simulated_home.hal
Found file(REL): ./cooling.hal
note: MAXV     max: 53.340 units/sec 3200.400 units/min
note: LJOG     max: 53.340 units/sec 3200.400 units/min
note: LJOG default: 30.480 units/sec 1828.800 units/min
note: jog_order='XYZ'
note: jog_invert=set()
[2026-10-19 23:05:07.041] [info] task: main loop took 0.026621 seconds

[2026-10-19 23:05:16.718] [info] task: main loop took 0.026869 seconds

[2026-10-19 23:05:25.208] [error] Exceeded POSITIVE soft limit (254.00000) on joint 1


[2026-10-19 23:05:25.208] [error] Joint must be unhomed, jogged into limits, rehomed

[2026-10-19 23:05:25.218] [info] task: main loop took 0.018986 seconds

[2026-10-19 23:05:25.299] [info] task: main loop took 0.018485 seconds

Shutting down and cleaning up LinuxCNC...
[2026-10-19 23:05:33.922] [info] task: 28470 cycles, min=0.000001, max=0.026869, avg=0.001068, 4 latency excursions (> 10x expected cycle time of 0.001000s)

[grandixximo]

@hdiethelm, I agree the split between errors and warnings and the other levels is the weak point, and your screenshot shows a second bug on the GUI side. Here is a middle step that I think gets your rule without the big sweep:

• Every rtapi_print_msg() message is one line, at every level: the uspace default handlers add the newline when the text lacks one. rtapi_print() still prints like printf. The output stage owns the line end, as you propose, but a format that already ends in \n prints the same, so the existing ones and their translations do not have to change now. New code can leave the newline out, and a later sweep, or the move to a logging library, can drop the old ones mechanically.
• The places that build one line from several calls print it with one: motion's command debug output (25 fragments), the rtapi_app cpuset report, the PPMC slot scan, halcmd's command echo and the two hm2_modbus frame dumps. mesa_pktgyro_test prints a byte per message and now comes out a byte per line, which reads better than today.
• Task drops the newline at the end of an operator error, so the blank line in your screenshot goes away in every GUI at once. Motion's reportError() adds its console newline only when the text lacks one; 5 of its callers end in \n and printed a blank line.

For scale, a scan of src/ finds 3174 rtapi_print_msg() calls, directly or through driver macros; 197 lack the newline: 70 errors and warnings, 9 info and 118 debug.

Tested with a component that prints one error without and one with the newline, loaded into the axis sim: on master the console shows guierr: no newlineguierr: with newline and the error channel hands the GUI 'guierr: with newline\n'; with these commits both are clean. tests/rtapi-msg-newline now covers all levels, an error that already has its newline, and an rtapi_print() line in two parts. The full suite passes apart from blendmath, which does not build with GCC 14 (#4676).

The RTAI kernel handler is unchanged.

The three commits are on msg-one-line. @BsAtHome, this is your fix at the endpoint, extended to every level. If you both agree, I will put them on this PR in place of the current commit.

[hdiethelm]

The three commits are on msg-one-line. @BsAtHome, this is your fix at the endpoint, extended to every level. If you both agree, I will put them on this PR in place of the current commit.

I prefer msg-one-line. It is more a step in the right direction instead of a workaround.

RTAI uses rt_printk(), forwarded to printk() internally in RTAI which expects a newline at the end. I did some tests: If you miss the newline, sometimes the message is only shown after the next one has been printed. But it stays a line, even if there is no newline.
These two location should also be fixed, so RTAI is not broken after removing newlines. I can test it if desired, I have a VM with RTAI running.

linuxcnc/src/rtapi/rtai_rtapi.c

Line 439 in 062dc7c

rt_printk(buf);

linuxcnc/src/rtapi/rtai_ulapi.c

Line 273 in 062dc7c

vfprintf(stderr, fmt, args);

[andypugh]

Have you tested with the Touchy GUI? That has a single line status bar at the bottom of the screen.
Newlines might make errors disappear.

(As an aside, Touchy really could do with a way to view multi-line and multiple errors, at the moment you only see the last line of the last error. The obvious place would be a field in the status tab)

[BsAtHome]

First, there may be differences in how debug messages or non-debug messages are constructed. The debug messages are for the console. A GUI has no space or time to handle the flood. An example is:

linuxcnc/src/hal/drivers/mesa-hostmot2/hm2_modbus.c

Lines 497 to 501 in 062dc7c

	#ifdef DEBUG
	MSG_DBG("Sending cmd=%u to '%s' %i bytes", inst->cmdidx, inst->uart, cc->datalen);
	for(int i = 0; i < cc->datalen; i++) MSG_DBG(" 0x%02x", cc->data[i]);
	MSG_DBG("\n");
	#endif

It calls rtapi_print_msg() multiple time without newline and then terminates the line manually. Therefore, adding newlines automatically cannot be done for debugging. For errors and warnings it is probably alright because these messages are routed to the GUI, which cannot construct partial messages into one whole.

Second, all the rtapi_print_msg() formats need to be printf formats because it is used in the kernel and it is C code.

Third, when we are to define new logging, then I'd suggest we start thinking about more fine-grained control over informational and debug messages. You want to have a "channel" that identifies a part of the code and can be switched on/off. That reduces the clutter when trying to find something specific.

Fourth, logging is generally a mess and inconsistent. We need to unify both the messages' content and the way they are routed. Much of the user-space just routes to stdout/stderr without thought.

Fifth, placing log message in the code is not done consistently. We need to have a review of info/warn/error messages. When do we want to have a log message for what information including which content. That is a difficult one, but needs an answer. Then it needs to be implemented.

[grandixximo]

@BsAtHome, on the first point: msg-one-line changes exactly that dump, it prints the frame with one call:

#ifdef DEBUG
	char hex[3 * MAX_PKT_LEN + 1];
	MSG_DBG("Sending cmd=%u to '%s' %i bytes:%s\n", inst->cmdidx, inst->uart, cc->datalen,
		hexdump(hex, sizeof(hex), cc->data, cc->datalen));
#endif

A line built in parts is a set of separate messages, so whatever another thread or process prints between them lands in the middle of the line; in uspace each part of a realtime message is its own entry in the queue. One call per line keeps the line whole at any level. There were six such places in the tree, and the second commit changes them all. If you still want debug to stay printf-like, I can give the newline to error, warning and info only and leave debug as it is; @hdiethelm, would that work for you?

The formats stay printf formats; the handler only adds the newline after formatting. Agreed on the rest: channels, routing and a review of what we log belong to the new logging work, and this does not get in its way.

@andypugh, yes. Touchy's error line is a single-line label, so a newline never hides the text: GTK draws it in place as a ↵ glyph. I ran Touchy on master and with these commits, with errors from a test component (a newline at the end, at the start, in the middle, in the middle and at the end, at both ends, none, and one longer than 80 characters) and with real ones: an MDI error from the interpreter and two jog errors from motion, one without and one with a newline (JOG_INCR Mode is TELEOP, cannot jog joint). The only difference is that the ↵ at the end is gone; a newline at the start or in the middle and the cut at 80 characters show as on master. The console part of the change does not reach the GUIs; only the task commit does, and it only removes newlines at the end. Agreed on the aside: Touchy shows only the first 80 characters of the last error, and a list of errors on the Status tab would be a separate PR.

@hdiethelm, I added the two RTAI places in a fourth commit: the kernel handler ends a message that lacks the newline before rt_printk(), which now gets the text as an argument instead of as the format, and rtapi_print_msg() in RTAI user space does the same on stderr. I cannot build RTAI here, so a run on your VM would be welcome.

[hdiethelm]

First, there may be differences in how debug messages or non-debug messages are constructed. The debug messages are for the console. A GUI has no space or time to handle the flood. An example is:

linuxcnc/src/hal/drivers/mesa-hostmot2/hm2_modbus.c

Lines 497 to 501 in 062dc7c

	#ifdef DEBUG
	MSG_DBG("Sending cmd=%u to '%s' %i bytes", inst->cmdidx, inst->uart, cc->datalen);
	for(int i = 0; i < cc->datalen; i++) MSG_DBG(" 0x%02x", cc->data[i]);
	MSG_DBG("\n");
	#endif

It calls rtapi_print_msg() multiple time without newline and then terminates the line manually. Therefore, adding newlines automatically cannot be done for debugging. For errors and warnings it is probably alright because these messages are routed to the GUI, which cannot construct partial messages into one whole.

Indeed, there are many places you might miss due to they use defines like in this case. Never the less, one message should be one message and this should be fixed in my opinion.

Having different ways messages should be constructed depending on the severity level is inconsistent and bug prone.

Doing the example above with prink() will generate funny results. Even if you use it for debugging:

	//bad
	printk(KERN_INFO "Hello, ");
	printk(KERN_INFO "world 1\n");
	//good
	printk(KERN_INFO "Hello, world 2\n");
	printk(KERN_INFO "Hello,\nworld 3\n");

->

[13752.207536] Hello, 
[13752.207538] world 1
[13752.207539] Hello, world 2
[13752.207539] Hello,
               world 3

Second, all the rtapi_print_msg() formats need to be printf formats because it is used in the kernel and it is C code.

In turn, this would mean a newline should be added here and drop this PR:

linuxcnc/src/emc/motion/homing.c

Line 282 in eab7726

rtapi_print_msg(RTAPI_MSG_ERR,_("j%d end of move in home state %d"),jno, H[jno].home_state);

But it does not have to be, you can add the newline just before rt_printk() in rtai_rtapi.c.

Third, when we are to define new logging, then I'd suggest we start thinking about more fine-grained control over informational and debug messages. You want to have a "channel" that identifies a part of the code and can be switched on/off. That reduces the clutter when trying to find something specific.

Agreed. The way it is right now, it is often easier to just redefine a message to ERR temporarily instead of dealing with the flood of debug messages.

Fourth, logging is generally a mess and inconsistent. We need to unify both the messages' content and the way they are routed. Much of the user-space just routes to stdout/stderr without thought.

Fifth, placing log message in the code is not done consistently. We need to have a review of info/warn/error messages. When do we want to have a log message for what information including which content. That is a difficult one, but needs an answer. Then it needs to be implemented.

Also agreed. Using ERR for info messages which are important for the user to see just due to there is no other option is fully inconsistent.

For many messages, it is unclear if it is an issue or just a don't care. I had a hard time figuring out the reason for a test fail due to this. You got 100's of messages. Most are info or warning but one is a hard fail. No way to see which one.

Normally, the default log level where your are not spawned with 1000's of debug messages should be info, might be warn. But for sure not error.

[hdiethelm]

@grandixximo Our responses just crossed. Yes, an additional issue with using multiple messages to create one is the race conditions it will generate.

Anyone not wanting to use temporary strings for quick debug messages during development can still use rtapi_print() which behaves still exactly like printf() including the possible races. But I for debug messages that go into a PR, it should be one message, even if DBG. Otherwise, this will generate cleanup effort as soon as we like to do proper logging.

@hdiethelm, I added the two RTAI places in a fourth commit: the kernel handler ends a message that lacks the newline before rt_printk(), which now gets the text as an argument instead of as the format, and rtapi_print_msg() in RTAI user space does the same on stderr. I cannot build RTAI here, so a run on your VM would be welcome.

Looks good in the code. Tag me when the discussion has settled and I will test it. The RTAI VM is a bit cumbersome, it has fixed screen resolution, no copy paste from host, crashes from time to time and so on.

[BsAtHome]

Right, split debug messages need fixing. Not really nice with the static buffer, though, especially not nice because it is on the RT thread's stack (compiler may generate frame size problems). These debug message will get split in the kernel (not often used), but on the console they generally do not. But, yes, it is a race which message comes first when multiple threads are competing (not likely with mostly only one RT thread).

We also need to separate the RT messages from the non-RT message. It is often a messy business.

RT needs to use rtapi_print*(). Anything else should be using the rcs_print*(). Other forked processes need to be incorporated into the message log stream. This will be the most tricky part.

About channels, has anyone ever looked at Wine? They have a channelized message system that is rather fine-grained. Especially helpful with separating the DLLs' messages and allows only showing what you really need. Could be inspirational.

[grandixximo]

@BsAtHome, good catch on the stack. The dump buffer was 3 * MAX_PKT_LEN + 1 bytes; with -fstack-usage, parse_data_frame() went to 1152 bytes and send_modbus_pkt() to 880. The dump now prints one message for every 16 bytes from a 49-byte buffer, so both are back to their size on master, and the largest frame in the file is process() again:

// Debug dump of a frame, one message for every 16 bytes
static void dump_frame(const char *what, unsigned cmdidx, const rtapi_u8 *data, unsigned len)
{
	for(unsigned i = 0; i < len; i += 16) {
		char hex[16 * 3 + 1] = "";
		unsigned n = 0;
		for(unsigned j = i; j < len && j < i + 16; j++)
			n += rtapi_snprintf(hex + n, sizeof(hex) - n, " %02x", data[j]);
		MSG_DBG("%s cmd=%u [%u]:%s\n", what, cmdidx, i, hex);
	}
}

Agreed on splitting the RT messages from the rest, with rcs_print*() outside RT; that belongs to the logging work, with the channels. Wine's debug channels, with a class per message (err, warn, fixme, trace) and a switch per channel, look like a good model.

I moved the four commits onto this PR and updated its description. I think at least the shape of this PR is settled; whatever comes next, we will see. @hdiethelm, it is ready for the RTAI run when you have time.

[rene-dev]

@grandixximo

Agreed on splitting the RT messages from the rest, with rcs_print*() outside RT; that belongs to the logging work, with the channels. Wine's debug channels, with a class per message (err, warn, fixme, trace) and a switch per channel, look like a good model.

Please dont use rcs_print, use https://github.com/LinuxCNC/linuxcnc/blob/master/src/emc/logutil.hh#L37

[BsAtHome]

Well, I objected to prematurely changing the logging infrastructure. Logutil is just a half fix of the old system without actually fixing the real problem IMO.

[BsAtHome]

Please dont use rcs_print

FWIW, if it has been replaced, why is it still present in the code and why is it still in libnml? Just changing logging by renaming (and using libfmt) does not set the stage for the real changes necessary IMO.

[hdiethelm]

@grandixximo
RTAI testing was medium successful: halcompile does not behave, probably broken but might be it needs sudo for RTAI. By copying msgline.comp in the tree and loading it by hand, at least I got:

[ 1402.969714] RTAPI: ERROR: Unexpected realtime delay on task 1
               This Message will only display once per session.
               Run the Latency Test and resolve before continuing.
[ 1422.345323] msgline: error in the thread
[ 1422.345345] msgline: error with its newline
[ 1422.345347] msgline: print 
[ 1422.345347] in parts

So it looks your code works, just other issues. Like every time I test RTAI for a change... ;-) RTAI also does not suport changing log level, so only errors are shown.

print in parts is split due to this is what printk does, no way around it I think.

[rene-dev]

FWIW, if it has been replaced, why is it still present in the code and why is it still in libnml? Just changing logging by renaming (and using libfmt) does not set the stage for the real changes necessary IMO.

its still in the code because libnml uses it internally, and there is no point in converting libnml as it will be removed anyway. It does set the stage, as there is now one place to implement the new system.

Well, I objected to prematurely changing the logging infrastructure. Logutil is just a half fix of the old system without actually fixing the real problem IMO.

Well, I also objected to your hal changes ;D There wasnt much of infrastructure, there was broken code. So far I have received Zero productive input on logging, So Im working on spdlog. Please continue the discussion in the logging discussion #4638 if you have Ideas.

[BsAtHome]

Well, I also objected to your hal changes ;D

I find this type of "jokes" very offensive (seriously).