Gnome Terminal staircase pattern

Question

I just upgraded from Ubuntu 20.04 to 22.04.2 (Linux 5.15.0-67), using XFCE desktop environment, with Gnome Terminal version 3.44.0. I have a script program to do backups which I have run essentially daily for years. This program both displays information to the terminal and writes information to a logfile.

On my first run of this program after the upgrade, I noticed an odd behavior, that sometimes a new line of output to the terminal will drop down one line, as expected, but will be in the next column after the preceding line, rather than at the far left column as expected. This doesn’t happen always, and I see it jump back and forth between expected behavior (all new lines start at the far left column), and this bizarre behavior for Bash in Linux.

I looked at the logfile, which has much more data than is written to the terminal, and all lines start in the far left column as expected.

I looked at the code generating this output. Sometimes it’s a simple “echo” command, sometimes an “echo -e”, and sometimes it’s an output message from some other command. Echo commands are teed to both the screen and the logfile, so both should behave the same way. I tried writing a test script to duplicate the issue, but it worked correctly, even with a loop of 500 echo commands.

Here’s the output from the terminal, showing the problem. For the longer lines, these would wrap in the terminal and the next line would start in the next column after the wrapped line.

> ******************************************************************
> ********** backup_type: tar_backup *******************************
> ******************************************************************
> 
> ******************************************************************
> ********** group: ubu_ssd1 ***************************************
> ******************************************************************
> 
> ******************************************************************
> ********** group: ubu_ssd1, element: root ************************
> ****************************************************************** mounting /dev/vg_ssd1/ubu_root_ssd1_snap on /mnt source device:
> /dev/vg_ssd1/ubu_root_ssd1_snap source directory: /mnt destination
> directory: /home/randy/Backup/home4/ubu_ssd1/update_2023_week_10 tar
> --directory=//mnt --create --one-file-system --no-check-device --auto-compress --warning=no-file-ignored --file=/home/randy/Backup/home4/ubu_ssd1/update_2023_week_10/ubu_root_ssd1_2023_week_10.3.tar
> . 
> --listed-incremental=/home/randy/Backup/home4/ubu_ssd1/update_2023_week_10/ubu_root_ssd1_2023_week_10.snar
> tar update "/mnt" to 
> "/home/randy/Backup/home4/ubu_ssd1/update_2023_week_10/ubu_root_ssd1_2023_week_10.3.tar"
> completed at 20230308-03:16:23. Elapsed time:  0 hrs  0 min 30 sec
> 
> ******************************************************************
>                                                                   ********** group: ubu_ssd1, element: boot ************************
>                                 ******************************************************************
>                                                                                                   source device: sdb8
>                  source directory: /boot
>                                         destination directory: /home/randy/Backup/home4/ubu_ssd1/update_2023_week_10
>                 tar --directory=//boot --create --one-file-system --no-check-device --auto-compress --warning=no-file-ignored --file=/home/randy/Backup/home4/ubu_ssd1/update_2023_week_10/ubu_boot_ssd1_2023_week_10.3.tar
> . 
> --listed-incremental=/home/randy/Backup/home4/ubu_ssd1/update_2023_week_10/ubu_boot_ssd1_2023_week_10.snar
>                              tar update "/boot" to  "/home/randy/Backup/home4/ubu_ssd1/update_2023_week_10/ubu_boot_ssd1_2023_week_10.3.tar"
> completed at 20230308-03:16:26.
>                                                                          Elapsed time:  0 hrs  0 min  0 sec
> 
> ******************************************************************
> ********** group: ubu_ssd1, element: home ************************
> ****************************************************************** mounting /dev/vg_ssd1/ubu_home_ssd1_snap on /mnt
>                                                         source device: /dev/vg_ssd1/ubu_home_ssd1_snap   source directory: /mnt
>                         destination directory: /home/randy/Backup/home4/ubu_ssd1/update_2023_week_10
>                                                                                                    tar --directory=//mnt --create --one-file-system --no-check-device
> --auto-compress --warning=no-file-ignored --file=/home/randy/Backup/home4/ubu_ssd1/update_2023_week_10/ubu_home_ssd1_2023_week_10.3.tar
> . 
> --listed-incremental=/home/randy/Backup/home4/ubu_ssd1/update_2023_week_10/ubu_home_ssd1_2023_week_10.snar
>            tar update "/mnt" to  "/home/randy/Backup/home4/ubu_ssd1/update_2023_week_10/ubu_home_ssd1_2023_week_10.3.tar"
> completed at 20230308-03:16:58.
>                                                       Elapsed time:  0 hrs  0 min 33 sec
> 
>                                                                                         ******************************************************************
>                                                       ********** group: data *******************************************
>                     ******************************************************************
> 
>                                                                                       ******************************************************************
>                                                     ********** group: data, element: data ****************************
>                   ******************************************************************
>                                                                                     mounting /dev/vg_data_hd5/data_lv_snap on /mnt
>                                       source device: /dev/vg_data_hd5/data_lv_snap
>                                                                                   source directory: /mnt
>     destination directory: /home/randy/Backup/home4/data/update_2023_week_10
>                                                                             tar --directory=//mnt --create --one-file-system --no-check-device
> --auto-compress --warning=no-file-ignored --file=/home/randy/Backup/home4/data/update_2023_week_10/data_hd5_2023_week_10.3.tar
> . 
> --listed-incremental=/home/randy/Backup/home4/data/update_2023_week_10/data_hd5_2023_week_10.snar
>                                                                       tar update "/mnt" to 
> "/home/randy/Backup/home4/data/update_2023_week_10/data_hd5_2023_week_10.3.tar"
> completed at 20230308-03:17:08.

Here’s the output from the logfile, with the extra lines stripped out, showing that it is written to properly.

******************************************************************
********** backup_type: tar_backup *******************************
******************************************************************


********** group: ubu_ssd1 ***************************************


********** group: ubu_ssd1, element: root ************************

mounting /dev/vg_ssd1/ubu_root_ssd1_snap on /mnt
source device: /dev/vg_ssd1/ubu_root_ssd1_snap
source directory: /mnt
destination directory: /home/randy/Backup/home4/ubu_ssd1/update_2023_week_10
tar --directory=//mnt --create --one-file-system --no-check-device --auto-compress --warning=no-file-ignored --file=/home/randy/Backup/home4/ubu_ssd1/update_2023_week_10/ubu_root_ssd1_2023_week_10.3.tar .  --listed-incremental=/home/randy/Backup/home4/ubu_ssd1/update_2023_week_10/ubu_root_ssd1_2023_week_10.snar
tar update "/mnt" to  "/home/randy/Backup/home4/ubu_ssd1/update_2023_week_10/ubu_root_ssd1_2023_week_10.3.tar"  completed at 20230308-03:16:23.
Elapsed time:  0 hrs  0 min 30 sec

********** group: ubu_ssd1, element: boot ************************

source device: sdb8
source directory: /boot
destination directory: /home/randy/Backup/home4/ubu_ssd1/update_2023_week_10
Entering function backup_tar
Entering function check_tar_increment
Returning from function check_tar_increment  with value: 3
tar --directory=//boot --create --one-file-system --no-check-device --auto-compress --warning=no-file-ignored --file=/home/randy/Backup/home4/ubu_ssd1/update_2023_week_10/ubu_boot_ssd1_2023_week_10.3.tar .  --listed-incremental=/home/randy/Backup/home4/ubu_ssd1/update_2023_week_10/ubu_boot_ssd1_2023_week_10.snar
tar update "/boot" to  "/home/randy/Backup/home4/ubu_ssd1/update_2023_week_10/ubu_boot_ssd1_2023_week_10.3.tar"  completed at 20230308-03:16:26.
Elapsed time:  0 hrs  0 min  0 sec

********** group: ubu_ssd1, element: home ************************

mounting /dev/vg_ssd1/ubu_home_ssd1_snap on /mnt
source device: /dev/vg_ssd1/ubu_home_ssd1_snap
source directory: /mnt
destination directory: /home/randy/Backup/home4/ubu_ssd1/update_2023_week_10
tar --directory=//mnt --create --one-file-system --no-check-device --auto-compress --warning=no-file-ignored --file=/home/randy/Backup/home4/ubu_ssd1/update_2023_week_10/ubu_home_ssd1_2023_week_10.3.tar .  --listed-incremental=/home/randy/Backup/home4/ubu_ssd1/update_2023_week_10/ubu_home_ssd1_2023_week_10.snar
tar update "/mnt" to  "/home/randy/Backup/home4/ubu_ssd1/update_2023_week_10/ubu_home_ssd1_2023_week_10.3.tar"  completed at 20230308-03:16:58.
Elapsed time:  0 hrs  0 min 33 sec

********** group: data *******************************************


********** group: data, element: data ****************************

mounting /dev/vg_data_hd5/data_lv_snap on /mnt
source device: /dev/vg_data_hd5/data_lv_snap
source directory: /mnt
destination directory: /home/randy/Backup/home4/data/update_2023_week_10
tar --directory=//mnt --create --one-file-system --no-check-device --auto-compress --warning=no-file-ignored --file=/home/randy/Backup/home4/data/update_2023_week_10/data_hd5_2023_week_10.3.tar .  --listed-incremental=/home/randy/Backup/home4/data/update_2023_week_10/data_hd5_2023_week_10.snar
tar update "/mnt" to  "/home/randy/Backup/home4/data/update_2023_week_10/data_hd5_2023_week_10.3.tar"  completed at 20230308-03:17:08.

Just because you’d be interested, here’s some code snippets for the offending write lines.

echo "mounting ${mntpnt_volume} on ${mntpnt}" | tee -a ${gc_logfile};

echo "source device: ${source_device}" | tee -a "${gc_logfile}";
echo "source directory: ${source_directory}" | tee -a "${gc_logfile}";
echo "destination directory: ${dest_directory}" | tee -a "${gc_logfile}";
echo -e "\n${c_stars1}${c_stars2}"  | tee -a ${gc_logfile};
echo -e "${c_stars1} ${star_gap_string}"        

"${c_stars2:${star_gap}}"   | tee -a ${gc_logfile};
echo -e "${c_stars1}${c_stars2}"    | tee -a ${gc_logfile};

This code was working just fine the day before when I was in 20.04. Any ideas?

EDIT:

See my answer below, which involves timing of calling PulseAudio paplay in a command line, which I spawn as a subprocess from root, which requires resetting the environmental variable XDG_RUNTIME_DIR.

I tried to add the tags paplay and XDG_RUNTIME_DIR, but StackExchange says I don't have enough reputation to use those words as tags. I'm just trying to make it easier for others who find themselves in a similar situation. I guess I gotta go get some street cred.

You don't need to end each command with ; since bash splits commands on newline already. — Maximilian Ballard, Mar 09 '23 at 06:25
The -e in echo -e can translate some characters in the output to e.g. tabs, newlines, spaces and others … try using just echo or even printf if your output requires special formatting and see if this solves it … i.e. It could be that your output is causing this and not the terminal … @MaximilianBallard True ; is not needed when each command is a new line but it doesn’t harm either. — Raffa, Mar 09 '23 at 06:42
On a second thought since you say the same output looks okay in the log file, have a look at this: https://askubuntu.com/q/1457265 — Raffa, Mar 09 '23 at 06:53
@MaximilianBallard and Raffa, you are correct that the ";" is not necessary, but I developed it as a habit early on because with color scheme feedback in the editor, it's a quick indication if I have an open quote, bracket, or parenthesis in the line. Similarly, brackets and quotes are not always necessary around variable names, but I consider it good practice to do it consistently (although I see I missed in a few places) — Randyman99, Mar 09 '23 at 08:01
@Raffa, thank you for that link, it seems to be the same problem, though the one answer of running "sudo visudo" and turning of "use_pty" doesn't seem practical, even if it would fix the problem. In another comment to that post, someone mentioned using "stty -a" to list terminal line settings. I found if I preceded the echo command in my test script with "stty -onlcr", then the problem reoccurred exactly as above. I was able to revert to normal behavior with the command "stty -nl". I added this command to multiple places in my program, and it worked sometimes but not always. More tomorrow. — Randyman99, Mar 09 '23 at 11:07
So far, I have added the line "stty -nl" 24 times in various places in my program, before and after each echo command that initiates its output in anything but the first column, and the problem still persists, although less often. Even if it did solve the problem completely, this would be a workaround and not a fix. Other than with the "stty" command, I can't recreate the problem in a test script. Something definitely seems to be broken in the Bash output to the terminal with the upgrade to 22.04. — Randyman99, Mar 10 '23 at 06:46
I did try this with XFCE terminal (0.8.10), and get the exact same column off-spacing as with Gnome terminal, so it doesn't seem to be specific to the terminal. — Randyman99, Mar 10 '23 at 08:47
@Raffa, I tried converting all the "echo -e" statements to straight "echo" statements, and it didn't make any difference. I converted back to "echo -e" and put a "/r/n" at the end, and that helped for those statements. But a plain "echo" statement should contain that implicitly, and they seem to not do that any longer. I shouldn't have to do that for every "echo" statement. I use "printf" statements for writing specific format to "floating point" representation variables, and also for notify-send statements, but not to terminal output. — Randyman99, Mar 10 '23 at 10:53
IIRC ... I don't think that echo inserts the carriage return \r automatically neither in previous versions nor in recent ones ... It might be worth noting there are two of them the shell(i.e. bash) builtin echo that you can view help with help echo and the external /bin/echo command that is part of coreutils and it's help can be viewed with man echo ... You can find which one your shell is using by running type echo — Raffa, Mar 11 '23 at 08:28
@Raffa, with the "-e" option, you are correct. This allows for concatenating the outputs of two echo commands on the same line, or having a succeeding line start in a specific column with respect to the preceding command. A normal echo command without the "-e" option will start where the cursor was left after the preceding write to the terminal, but will end with putting the cursor one line down and in the far left column (under normal behavior). BW way, I did "type echo" and both of my terminals responded with "echo is a shell builtin". — Randyman99, Mar 11 '23 at 09:05
Nice research effort :) ... I get what you mean ... e.g. something similar to the effect of for i in {1..10}; do echo -e "\033["$i"C$i"; done and for i in {1..10}; do echo -e "\033["$i"C$i"; echo "$i"; done ... This has nothing to do with the terminal but rather your script/code ... Background processes will still write stdout and stderr to their parent terminal. — Raffa, Mar 11 '23 at 10:33

Randyman99 · Answer 1 · 2023-03-11T08:56:43.403

Okay, I figured this out, and it goes back many years. I had written functions to handle different sound outputs, which I play at different points in my program and for different conditions. The PulseAudio paplay function takes some time to complete, so I thought it would be a good idea to run it as a child process, so the parent process could move on to other things. All was well and good.

If my memory serves me correctly (which isn't always the case), things changed some years back with a version upgrade, and I had to add an if statement to check if this function was being run as root, and handle the paplay call differently with setting XDG_RUNTIME_DIR. But this caused an error condition which perhaps was similar to what I'm experiencing now -- I don't remember. The error condition only happens if I'm spawning the root condition paplay call to a child process. I found the program would work correctly if I put a sleep delay in of 0.7 seconds, which was how long it took the paplay call to complete, even offloaded as a subprocess. I never did discover WHY it behaved this way, but I just put the 0.7 second sleep interval in all my sound functions and lived with it. Here's one of the sound functions:

function play_norm_sound {

check if we're running as root.
if [[ $EUID -eq 0 ]]; then
sudo -u '#1000' XDG_RUNTIME_DIR=/run/user/1000       

paplay "/usr/share/sounds/KDE-Im-Contact-Out.ogg" &
else
paplay "/usr/share/sounds/KDE-Im-Contact-Out.ogg" &
fi
sleep 0.7;
return 0;
}

What is happening now is that the paplay call now takes about 1.1 seconds to complete, so the 0.7 seconds isn't long enough. During the gap between the 0.7 seconds of the sleep interval and the 1.1 seconds to complete the paplay function, the bizarre behavior happens. That's why sometimes I would see it correct itself, and then later behave strangely again. I play a lot of sounds as the program goes through loops and completes certain operations.

I thought of why should I bother spawning a child process and then put in a sleep interval for it to complete? Perhaps in some future upgrade the time interval will be even greater. I could just take out the spawn character (the "&" at the end of the line), and let it run within the confines of the parent shell, and delete the sleep interval call. I can leave the non-root condition to spawn to a child process as it originally did.

Here's the new code:

function play_norm_sound {

check if we're running as root.
if [[ $EUID -eq 0 ]]; then
sudo -u '#1000' XDG_RUNTIME_DIR=/run/user/1000     

paplay "/usr/share/sounds/KDE-Im-Contact-Out.ogg";
else
paplay "/usr/share/sounds/KDE-Im-Contact-Out.ogg" &
fi
return 0
}

I don't consider this a fix, because I should be able to spawn a child process, which would have the program run more efficiently, without things behaving so oddly. But this is a workaround, and that might be as far as I get with it.

BTW, I found if the program ends while the terminal is displaying the strange behavior, the bad behavior persists in the terminal from that point on, as well as not displaying any keyboard input. This is regardless of running any stty commands or changing the terminal preferences. The only thing to do is close the tab, open a new one, or close the terminal window. This is true of both the Gnome and the xfce terminals.

What you experience is often called "staircase effect" and is caused by "stty -onlcr" aka the lack of automatic LF -> CR LF conversion. "I should be able to spawn a child process, which would have the program run more efficiently, without things behaving so oddly" -- correct behavior depends on all parties who have access to the terminal playing nicely and cooperatively with each other, which doesn't seem to be the case here. — egmont, Mar 13 '23 at 09:54
@egmont, yes I played around with "stty -onlcr" and "stty -nl", and while I could recreate the effect and stop it again, I couldn't disable it when it was occurring by forces which were causing my problem. The way I discovered my solution was to put "sleep" commands of varying times in both the parent process and child process, along with numerous "echo" commands so I could see what was running when and when the effect started and when it stopped." — Randyman99, Mar 18 '23 at 22:19
It must be some stty setting. In another terminal run in a loop a stty -a dumping to a file along with a timestamp, every 0.1 seconds or so, redirecting its stdin (yes stty works on its stdin) to the terminal in question, I'm sure you'll spot the change. — egmont, Mar 19 '23 at 07:14
The problem was the stty -nl had no effect in the script when it went into stairstep mode. I could go back and forth within the script with stty -onlcr and stty -nl, and that would change back and forth, but once the stairstepping started because of the sudo -u '#1000' XDG_RUNTIME_DIR=/run/user/1000 paplay "/usr/share/sounds/KDE-Im-Contact-Out.ogg" & command, nothing would stop it other than time for the spawned command to complete. That was my conundrum, which I solved by NOT spawning it and just letting it run before the next command in the script, which slows the script down. — Randyman99, Mar 23 '23 at 10:22

Gnome Terminal staircase pattern

EDIT:

1 Answers1

check if we're running as root.

check if we're running as root.

Linked