--- Begin Message ---
- To: submit@bugs.debian.org
- Subject: [linux-image-4.14.0-2-amd64] Function g_file_copy() from libglib2.0-0 hangs when copying small files from CIFS-Share. This is relevant for Thunar filemanager.
- From: reiny <hackaria@web.de>
- Date: Mon, 1 Jan 2018 23:38:43 +0100
- Message-id: <20180101232944.334a54be@vbxdebsid>
Package: linux-image-4.14.0-2-amd64
Version: 4.14.0-2-amd64
Severity: critical
--- Please enter the report below this line. ---
The function g_file_copy() from libglib2.0-0 hangs when copying a small
file from a mounted CIFS-Share. Since the thunar filemanager is using
this function to copy files, the whole copy process hangs and the
progress bar does not close again. I built a debug version of thunar
and found with gdb that the function g_file_copy() uses the systemcall
splice(). There seems to bee the problem. When Thunar hangs the
debugger gives the following output:
[debug]> thread 4
[debug][Switching to thread 4 (Thread 0x7fffe7fff700 (LWP 8037))]
[debug]#0 0x00007ffff4a2f2a3 in splice () at ../sysdeps/unix/syscall-template.S:84
[debug]84 in ../sysdeps/unix/syscall-template.S
[debug]>>>>>>cb_gdb:
[debug]> bt 30
[debug]#0 0x00007ffff4a2f2a3 in splice () at ../sysdeps/unix/syscall-template.S:84
[debug]#1 0x00007ffff54b3cae in () at /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
[debug]#2 0x00007ffff54ba44c in g_file_copy () at /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
[debug]#3 0x0000555555613619 in ttj_copy_file (job=0x555555980370, source_file=0x555555c99440, target_file=0x555555cd9ae0, copy_flags=G_FILE_COPY_NOFOLLOW_SYMLINKS, merge_directories=1, error=0x7fffe7ffe8e0) at thunar-transfer-job.c:396
[debug]#4 0x0000555555613a28 in thunar_transfer_job_copy_file (job=0x555555980370, source_file=0x555555c99440, target_file=0x555555cd9ae0, error=0x7fffe7ffe980) at thunar-transfer-job.c:518
[debug]#5 0x0000555555613f4e in thunar_transfer_job_copy_node (job=0x555555980370, node=0x5555559ddce0, target_file=0x555555cd9ae0, target_parent_file=0x5555559c3680, target_file_list_return=0x0, error=0x7fffe7ffea30) at thunar-transfer-job.c:655
[debug]#6 0x0000555555613fc4 in thunar_transfer_job_copy_node (job=0x555555980370, node=0x5555559c3a80, target_file=0x5555559c3680, target_parent_file=0x0, target_file_list_return=0x7fffe7ffeac8, error=0x7fffe7ffeac0) at thunar-transfer-job.c:671
[debug]#7 0x0000555555614d62 in thunar_transfer_job_execute (job=0x555555980370, error=0x7fffe7ffeb60) at thunar-transfer-job.c:1062
[debug]#8 0x00007ffff79ae08d in exo_job_scheduler_job_func (scheduler_job=0x555555c02080, cancellable=<optimized out>, user_data=<optimized out>) at exo-job.c:317
[debug]#9 0x00007ffff54cfc96 in () at /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
[debug]#10 0x00007ffff54f6cf6 in () at /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
[debug]#11 0x00007ffff4f76000 in () at /lib/x86_64-linux-gnu/libglib-2.0.so.0
[debug]#12 0x00007ffff4f75635 in () at /lib/x86_64-linux-gnu/libglib-2.0.so.0
[debug]#13 0x00007ffff4cec519 in start_thread (arg=0x7fffe7fff700) at pthread_create.c:456
[debug]#14 0x00007ffff4a2ea4f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
[debug]>>>>>>cb_gdb:
[debug]> if 1
disassemble $pc,$pc+50
info frame
end
[debug] > > >Dump of assembler code from 0x7ffff4a2f2a3 to 0x7ffff4a2f2d5:
[debug]=> 0x00007ffff4a2f2a3 <splice+51>: mov rdi,QWORD PTR [rsp]
[debug] 0x00007ffff4a2f2a7 <splice+55>: mov rdx,rax
[debug] 0x00007ffff4a2f2aa <splice+58>: call 0x7ffff4a3b690 <__libc_disable_asynccancel>
[debug] 0x00007ffff4a2f2af <splice+63>: mov rax,rdx
[debug] 0x00007ffff4a2f2b2 <splice+66>: add rsp,0x8
[debug] 0x00007ffff4a2f2b6 <splice+70>: cmp rax,0xfffffffffffff001
[debug] 0x00007ffff4a2f2bc <splice+76>: jae 0x7ffff4a2f2bf <splice+79>
[debug] 0x00007ffff4a2f2be <splice+78>: ret
[debug] 0x00007ffff4a2f2bf <splice+79>: mov rcx,QWORD PTR [rip+0x2afbb2] # 0x7ffff4cdee78
[debug] 0x00007ffff4a2f2c6 <splice+86>: neg eax
[debug] 0x00007ffff4a2f2c8 <splice+88>: mov DWORD PTR fs:[rcx],eax
[debug] 0x00007ffff4a2f2cb <splice+91>: or rax,0xffffffffffffffff
[debug] 0x00007ffff4a2f2cf <splice+95>: ret
[debug] 0x00007ffff4a2f2d0 <sysinfo+0>: mov eax,0x63
[debug]End of assembler dump.
[debug]Stack level 0, frame at 0x7fffe7ffe610:
[debug] rip = 0x7ffff4a2f2a3 in splice (../sysdeps/unix/syscall-template.S:84); saved rip = 0x7ffff54b3cae
[debug] called by frame at 0x7fffe7ffe660
[debug] source language asm.
[debug] Arglist at 0x7fffe7ffe5f8, args:
[debug] Locals at 0x7fffe7ffe5f8, Previous frame's sp is 0x7fffe7ffe610
[debug] Saved registers:
[debug] rip at 0x7fffe7ffe608
[debug]>>>>>>cb_gdb:
[debug]> disassemble /m 0x00007ffff4a2f2a3
[debug]Dump of assembler code for function splice:
[debug]84 in ../sysdeps/unix/syscall-template.S
[debug] 0x00007ffff4a2f270 <+0>: cmp DWORD PTR [rip+0x2b5489],0x0 # 0x7ffff4ce4700 <__libc_multiple_threads>
[debug] 0x00007ffff4a2f277 <+7>: jne 0x7ffff4a2f28c <splice+28>
[debug] 0x00007ffff4a2f279 <+0>: mov r10,rcx
[debug] 0x00007ffff4a2f27c <+3>: mov eax,0x113
[debug] 0x00007ffff4a2f281 <+8>: syscall
[debug] 0x00007ffff4a2f283 <+10>: cmp rax,0xfffffffffffff001
[debug] 0x00007ffff4a2f289 <+16>: jae 0x7ffff4a2f2bf <splice+79>
[debug] 0x00007ffff4a2f28b <+18>: ret
[debug] 0x00007ffff4a2f28c <+28>: sub rsp,0x8
[debug] 0x00007ffff4a2f290 <+32>: call 0x7ffff4a3b630 <__libc_enable_asynccancel>
[debug] 0x00007ffff4a2f295 <+37>: mov QWORD PTR [rsp],rax
[debug] 0x00007ffff4a2f299 <+41>: mov r10,rcx
[debug] 0x00007ffff4a2f29c <+44>: mov eax,0x113
[debug] 0x00007ffff4a2f2a1 <+49>: syscall
[debug]=> 0x00007ffff4a2f2a3 <+51>: mov rdi,QWORD PTR [rsp]
[debug] 0x00007ffff4a2f2a7 <+55>: mov rdx,rax
[debug] 0x00007ffff4a2f2aa <+58>: call 0x7ffff4a3b690 <__libc_disable_asynccancel>
[debug] 0x00007ffff4a2f2af <+63>: mov rax,rdx
[debug] 0x00007ffff4a2f2b2 <+66>: add rsp,0x8
[debug] 0x00007ffff4a2f2b6 <+70>: cmp rax,0xfffffffffffff001
[debug] 0x00007ffff4a2f2bc <+76>: jae 0x7ffff4a2f2bf <splice+79>
[debug]85 in ../sysdeps/unix/syscall-template.S
[debug] 0x00007ffff4a2f2be <+78>: ret
[debug]86 in ../sysdeps/unix/syscall-template.S
[debug] 0x00007ffff4a2f2bf <+79>: mov rcx,QWORD PTR [rip+0x2afbb2] # 0x7ffff4cdee78
[debug] 0x00007ffff4a2f2c6 <+86>: neg eax
[debug] 0x00007ffff4a2f2c8 <+88>: mov DWORD PTR fs:[rcx],eax
[debug] 0x00007ffff4a2f2cb <+91>: or rax,0xffffffffffffffff
[debug] 0x00007ffff4a2f2cf <+95>: ret
[debug]End of assembler dump.
[debug]>>>>>>cb_gdb:
To be sure it is not a problem of Thunar itself I wrote a small program
that copies a file from a mounted CIFS-Share to a local folder:
#include <stdio.h>
#include <stdlib.h>
#include <gio/gio.h>
#include <string.h>
#include <stdbool.h>
#include <pthread.h>
//Global vars
gpointer progress_callback_data;
bool run_progress_thread = true;
struct progess
{
goffset num_bytes_copied;
goffset total_bytes_to_copy;
gpointer user_data;
gdouble percent;
}copy_progress;
//Callback function for the progress of g_file_copy()
void progress_callback(goffset num_bytes_copied, goffset
total_bytes_to_copy, gpointer user_data) {
copy_progress.num_bytes_copied = num_bytes_copied;
copy_progress.total_bytes_to_copy = total_bytes_to_copy;
copy_progress.user_data = user_data;
copy_progress.percent = ((gdouble) num_bytes_copied / (gdouble)
total_bytes_to_copy) * 100.0; //printf("total_bytes_to_copy=%lf\n",
copy_progress.percent); }
//Thread to print the current progress in percent
void *print_progress_thread()
{
printf("print_progress_thread() started...\n");
gdouble last_percent = 0.0;
while(run_progress_thread)
{
if (copy_progress.percent != last_percent)
{
printf("total_bytes_to_copy=%lf\n", copy_progress.percent);
last_percent = copy_progress.percent;
}
sleep(1);
}
printf("print_progress_thread() ended...\n");
return NULL;
}
int main()
{
const char file_name[] = "vdi-compact.bat"; //small file
//const char file_name[] = "Debian-Sid.vdi"; //big file
char source_path[] = "/home/.../server/misc/Debian-Sid/";
char *source_name = malloc(strlen(source_path) + strlen(file_name)
+ 1); strcpy(source_name, source_path);
strcat(source_name, file_name);
char destination_path[] = "/home/.../Downloads/";
char *destination_name = malloc(strlen(destination_path) +
strlen(file_name) + 1); strcpy(destination_name, destination_path);
strcat(destination_name, file_name);
printf("Source=%s\n",source_name);
printf("Destination=%s\n",destination_name);
printf("Try to copy the file...\n");
//Init struct copy_progress
copy_progress.num_bytes_copied = 0;
copy_progress.total_bytes_to_copy = 0;
copy_progress.user_data = NULL;
copy_progress.percent = 0.0;
//Start print_progress_thread
pthread_t progress_thread;
if(pthread_create(&progress_thread, NULL, print_progress_thread,
NULL)) {
fprintf(stderr, "Error creating thread\n");
return 1;
}
sleep(1);
//Init copy variables
GFile *source_file = g_file_parse_name(source_name);
GFile *destination_file = g_file_new_for_path(destination_name);
GFileCopyFlags copy_flags = G_FILE_COPY_ALL_METADATA ||
G_FILE_COPY_OVERWRITE; GCancellable *cancel_able =
g_cancellable_new (); GError *copyerror = NULL;
//Copy the file with g_file_copy() - In case of the bug, this
function blocks! if (g_file_copy(source_file, destination_file,
copy_flags, cancel_able, (GFileProgressCallback)progress_callback,
progress_callback_data, ©error))
{
printf("File successfully copied!\n");
}
else
{
g_message("%s", copyerror->message);
}
//End the thread and the program.
run_progress_thread = false;
sleep(1);
return 0;
}
The result is the same. Sometimes the function hangs up during the
copying process. Debugging the given program ends up in the same
result. The function hangs in the systemcall splice().
[debug]> thread 1
[debug]84 ../sysdeps/unix/syscall-template.S: Datei oder Verzeichnis nicht gefunden.
[debug][Switching to thread 1 (Thread 0x7ffff7fd5880 (LWP 8161))]
[debug]#0 0x00007ffff69af2a3 in splice () at ../sysdeps/unix/syscall-template.S:84
[debug]>>>>>>cb_gdb:
[debug]> bt 30
[debug]#0 0x00007ffff69af2a3 in splice () at ../sysdeps/unix/syscall-template.S:84
[debug]#1 0x00007ffff7556cae in () at /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
[debug]#2 0x00007ffff755d44c in g_file_copy () at /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
[debug]#3 0x000055555555507f in main () at /home/reiny/Dokumente/GFileCopy/main.c:89
[debug]>>>>>>cb_gdb:
[debug]> if 1
disassemble $pc,$pc+50
info frame
end
[debug] > > >
[debug]Dump of assembler code from 0x7ffff69af2a3 to 0x7ffff69af2d5:
[debug]=> 0x00007ffff69af2a3 <splice+51>: mov rdi,QWORD PTR [rsp]
[debug] 0x00007ffff69af2a7 <splice+55>: mov rdx,rax
[debug] 0x00007ffff69af2aa <splice+58>: call 0x7ffff69bb690 <__libc_disable_asynccancel>
[debug] 0x00007ffff69af2af <splice+63>: mov rax,rdx
[debug] 0x00007ffff69af2b2 <splice+66>: add rsp,0x8
[debug] 0x00007ffff69af2b6 <splice+70>: cmp rax,0xfffffffffffff001
[debug] 0x00007ffff69af2bc <splice+76>: jae 0x7ffff69af2bf <splice+79>
[debug] 0x00007ffff69af2be <splice+78>: ret
[debug] 0x00007ffff69af2bf <splice+79>: mov rcx,QWORD PTR [rip+0x2afbb2] # 0x7ffff6c5ee78
[debug] 0x00007ffff69af2c6 <splice+86>: neg eax
[debug] 0x00007ffff69af2c8 <splice+88>: mov DWORD PTR fs:[rcx],eax
[debug] 0x00007ffff69af2cb <splice+91>: or rax,0xffffffffffffffff
[debug] 0x00007ffff69af2cf <splice+95>: ret
[debug] 0x00007ffff69af2d0 <sysinfo+0>: mov eax,0x63
[debug]End of assembler dump.
[debug]Stack level 0, frame at 0x7fffffffe530:
[debug] rip = 0x7ffff69af2a3 in splice (../sysdeps/unix/syscall-template.S:84); saved rip = 0x7ffff7556cae
[debug] called by frame at 0x7fffffffe580
[debug] source language asm.
[debug] Arglist at 0x7fffffffe518, args:
[debug] Locals at 0x7fffffffe518, Previous frame's sp is 0x7fffffffe530
[debug] Saved registers:
[debug] rip at 0x7fffffffe528
[debug]>>>>>>cb_gdb:
[debug]> disassemble /m 0x00007ffff69af2a3
[debug]Dump of assembler code for function splice:
[debug]84 in ../sysdeps/unix/syscall-template.S
[debug] 0x00007ffff69af270 <+0>: cmp DWORD PTR [rip+0x2b5489],0x0 # 0x7ffff6c64700 <__libc_multiple_threads>
[debug] 0x00007ffff69af277 <+7>: jne 0x7ffff69af28c <splice+28>
[debug] 0x00007ffff69af279 <+0>: mov r10,rcx
[debug] 0x00007ffff69af27c <+3>: mov eax,0x113
[debug] 0x00007ffff69af281 <+8>: syscall
[debug] 0x00007ffff69af283 <+10>: cmp rax,0xfffffffffffff001
[debug] 0x00007ffff69af289 <+16>: jae 0x7ffff69af2bf <splice+79>
[debug] 0x00007ffff69af28b <+18>: ret
[debug] 0x00007ffff69af28c <+28>: sub rsp,0x8
[debug] 0x00007ffff69af290 <+32>: call 0x7ffff69bb630 <__libc_enable_asynccancel>
[debug] 0x00007ffff69af295 <+37>: mov QWORD PTR [rsp],rax
[debug] 0x00007ffff69af299 <+41>: mov r10,rcx
[debug] 0x00007ffff69af29c <+44>: mov eax,0x113
[debug] 0x00007ffff69af2a1 <+49>: syscall
[debug]=> 0x00007ffff69af2a3 <+51>: mov rdi,QWORD PTR [rsp]
[debug] 0x00007ffff69af2a7 <+55>: mov rdx,rax
[debug] 0x00007ffff69af2aa <+58>: call 0x7ffff69bb690 <__libc_disable_asynccancel>
[debug] 0x00007ffff69af2af <+63>: mov rax,rdx
[debug] 0x00007ffff69af2b2 <+66>: add rsp,0x8
[debug] 0x00007ffff69af2b6 <+70>: cmp rax,0xfffffffffffff001
[debug] 0x00007ffff69af2bc <+76>: jae 0x7ffff69af2bf <splice+79>
[debug]85 in ../sysdeps/unix/syscall-template.S
[debug] 0x00007ffff69af2be <+78>: ret
[debug]86 in ../sysdeps/unix/syscall-template.S
[debug] 0x00007ffff69af2bf <+79>: mov rcx,QWORD PTR [rip+0x2afbb2] # 0x7ffff6c5ee78
[debug] 0x00007ffff69af2c6 <+86>: neg eax
[debug] 0x00007ffff69af2c8 <+88>: mov DWORD PTR fs:[rcx],eax
[debug] 0x00007ffff69af2cb <+91>: or rax,0xffffffffffffffff
[debug] 0x00007ffff69af2cf <+95>: ret
[debug]End of assembler dump.
[debug]>>>>>>cb_gdb:
The debugger in both programs points to the same assembler code in the
splice() function:
[debug]=> 0x00007ffff4a2f2a3 <+51>: mov rdi,QWORD PTR [rsp]
The previous version of linux-image does not have this problem. It
seems the splice() function has been modified.
The described behaviour was tested on different computers with the same
result. Also debian testing has this problem which can damage the
destination file.
--- System information. ---
Architecture:
Kernel: Linux 4.14.0-2-amd64
Debian Release: buster/sid
500 unstable ftp.de.debian.org
--- Package information. ---
Depends (Version) | Installed
===========================================-+-===================
kmod | 24-1
linux-base (>= 4.3~) | 4.5
initramfs-tools (>= 0.120+deb8u2) | 0.130
OR linux-initramfs-tool |
Package Status (Version) | Installed
=======================================-+-===========
firmware-amd-graphics |
firmware-atheros |
firmware-bnx2 |
firmware-bnx2x |
firmware-brcm80211 |
firmware-cavium |
firmware-intelwimax |
firmware-intel-sound |
firmware-ipw2x00 |
firmware-ivtv |
firmware-iwlwifi |
firmware-libertas |
firmware-linux-nonfree |
firmware-misc-nonfree |
firmware-myricom |
firmware-netxen |
firmware-qlogic |
firmware-realtek |
firmware-samsung |
firmware-siano |
firmware-ti-connectivity |
xen-hypervisor |
Recommends (Version) | Installed
==================================-+-===========
firmware-linux-free | 3.4
irqbalance | 1.3.0-0.1
apparmor | 2.11.1-4
Suggests (Version) | Installed
=====================================-+-===========
linux-doc-4.14 |
debian-kernel-handbook |
grub-pc | 2.02-2
OR grub-efi-amd64 |
OR extlinux |
--- Output from package bug script ---
** Version:
Linux version 4.14.0-2-amd64 (debian-kernel@lists.debian.org) (gcc
version 7.2.0 (Debian 7.2.0-18)) #1 SMP Debian 4.14.7-1 (2017-12-22)
** Command line:
BOOT_IMAGE=/boot/vmlinuz-4.14.0-2-amd64
root=UUID=2244d22c-9782-40ac-9a6b-73580a2c4e5d ro quiet
** Tainted: O (4096)
* Out-of-tree module has been loaded.
** Kernel log:
--- End Message ---