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.