Bug 1045045

Summary: zypper ref fails with misleading "Cannot write file" message
Product: [openSUSE] openSUSE Tumbleweed Reporter: Thiago Macieira <thiago>
Component: BasesystemAssignee: E-mail List <bnc-team-screening>
Status: RESOLVED INVALID QA Contact: E-mail List <qa-bugs>
Severity: Critical    
Priority: P5 - None    
Version: Current   
Target Milestone: ---   
Hardware: 64bit   
OS: SUSE Other   
Whiteboard:
Found By: --- Services Priority:
Business Priority: Blocker: ---
Marketing QA Status: --- IT Deployment: ---

Description Thiago Macieira 2017-06-20 03:47:37 UTC
# zypper ref repo-oss
Retrieving repository 'openSUSE-Tumbleweed-Oss' metadata -----------------------------------------------------------------[|]
Cannot write file '/var/adm/mount/AP_0xVTlAMs/content'.

Abort, retry, ignore? [a/r/i/...? shows all options] (a): r
Retrieving repository 'openSUSE-Tumbleweed-Oss' metadata -----------------------------------------------------------------[|]
Cannot write file '/var/adm/mount/AP_0xdHsjZc/suse/setup/descr/appdata-screenshots.tar'.

Abort, retry, ignore? [a/r/i/...? shows all options] (a): 
[and so forth]

$ rpm -qi zypper
Name        : zypper
Version     : 1.13.28
Release     : 1.1
Architecture: x86_64
Install Date: Fri Jun  9 21:07:09 2017
$ rpm -qi libzypp
Name        : libzypp
Version     : 16.12.0
Release     : 1.1
Architecture: x86_64
Install Date: Fri Jun  9 21:06:50 2017

I have used zypper since those installations, including an "important=yes" update according to snapper.

There is no problem with the filesystem, there's plenty of disk space left.

Inspecting the strace -f log indicates that it's having absolutely no problem creating files in /var/adm/mount:

75898 open("/var/adm/mount/AP_0xVBJWTN/repodata/repomd.xml.new.zypp.lvF0H9", O_RDWR|O_CREAT|O_EXCL|O_CLOEXEC, 0600) = 5
75898 fcntl(5, F_GETFL)                 = 0x8002 (flags O_RDWR|O_LARGEFILE)
75898 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2845, ...}) = 0
75898 getpid()                          = 75898
75898 uname({sysname="Linux", nodename="tjmaciei-mobl1", ...}) = 0
75898 write(3, "2017-06-19 20:25:30 <1> tjmaciei-mobl1(75898) [zypp++] MediaMultiCurl.cc(doGetFileCopy):1320 dest: /var/adm/mount/AP_0xVBJWTN/repodata/repomd.xml\n", 146) = 146
75898 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2845, ...}) = 0
75898 getpid()                          = 75898
75898 uname({sysname="Linux", nodename="tjmaciei-mobl1", ...}) = 0
75898 write(3, "2017-06-19 20:25:30 <1> tjmaciei-mobl1(75898) [zypp++] MediaMultiCurl.cc(doGetFileCopy):1321 temp: /var/adm/mount/AP_0xVBJWTN/repodata/repomd.xml.new.zypp.lvF0H9\n", 162) = 162
75898 stat("/var/adm/mount/AP_0xVBJWTN/repodata/repomd.xml", 0x7fff5cd1c3e0) = -1 ENOENT (No such file or directory)
[later]
75898 rename("/var/adm/mount/AP_0xVBJWTN/repodata/repomd.xml.new.zypp.lvF0H9", "/var/adm/mount/AP_0xVBJWTN/repodata/repomd.xml") = 0
75898 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2845, ...}) = 0
75898 getpid()                          = 75898
75898 uname({sysname="Linux", nodename="tjmaciei-mobl1", ...}) = 0
75898 write(3, "2017-06-19 20:25:30 <1> tjmaciei-mobl1(75898) [zypp] PathInfo.cc(rename):673 rename /var/adm/mount/AP_0xVBJWTN/repodata/repomd.xml.new.zypp.lvF0H9 -> /var/adm/mount/AP_0xVBJWTN/repodata/repomd.xml\n", 197) = 197

There are no threads involved, otherwise I would suggest that it's a race condition. But it's clear that it's trying to open a file before the downloaded file is renamed to the target name.
Comment 1 Thiago Macieira 2017-06-20 03:57:29 UTC
Looks like this was a btrfs problem, even though the strace makes no sense either. Everything is working after erasing an old snapshot and balancing.