Bug 1538630

Please note that this issue is blocking RHV 4.2 and will introduce a regression on RHEV 4.1.

If it cannot be handled in time for RHEL 7.5, we will need to come up with our own workaround.

Hi, thanks for attaching logs.

I see that a write to the 'mode' attribute fails with "[Errno 22]
Invalid argument". It's not clear why that would happen, and
especially how NM is related to that, since according to logs it
treats bond interfaces as unmanaged.

Do you have a reproducer I can run? Or would it be possible to run
vdsm under strace (or maybe instrument it to print which bond options
it is trying to write)?

Hi Beniamino,
I will reproduce and contact you. Thanks

(In reply to Beniamino Galvani from comment #3)
> Hi, thanks for attaching logs.
> 
> I see that a write to the 'mode' attribute fails with "[Errno 22]
> Invalid argument". It's not clear why that would happen, and
> especially how NM is related to that, since according to logs it
> treats bond interfaces as unmanaged.
> 

When the hypervisor is loading, a bond property mapping is executed to map all possible bond modes and their default properties onto a json file. It is later on used by VDSM to calculate when a bond property is to be persisted in the config.
The mapping is done by creating a bond and setting it to a mode, scanning all its options and then removing it, repeating all of this for other modes (new bond is created for each mode).
There is another mapping, between the bond property value ID (numeric) and its string representation. For that, we change the value by ID and read its string representation.
Both mapping are expected to cause errors, especially when trying to input non existing value ID/s or modes (it is a scan after all).

Hi,

were you able to reproduce the problem? Is this a blocker?

(In reply to Beniamino Galvani from comment #7)
> Hi,
> 
> were you able to reproduce the problem? Is this a blocker?

Unfortunately no, i didn't manage to reproduce the issue, which is quite weird as it used to happen 100%. 

Dan, did you managed to reproduce the issue?

We have a reproduction. Beniamino, i have wrote the host details in the e-mail.

Hello,

I was able to reproduce the problem and I believe NetworkManager is
not involved here (the fact the problem happens only when NM is
running is probably because it causes more contention on sysfs
access).

Running the vdsm-tool gives the following error:


 [root@lynx23 ~]# /usr/bin/vdsm-tool dump-bonding-options
 (setting bondscan-jjJjsP mode to 0)
 (setting bondscan-jjJjsP mode to 1)
 Traceback (most recent call last):
   File "/usr/bin/vdsm-tool", line 219, in main
     return tool_command[cmd]["command"](*args)
   File "/usr/lib/python2.7/site-packages/vdsm/tool/network.py", line 94, in dump_bonding_options
     sysfs_options_mapper.dump_bonding_options()
   File "/usr/lib/python2.7/site-packages/vdsm/network/link/bond/sysfs_options_mapper.py", line 48, in dump_bonding_options
     jdump(_get_default_bonding_options(), f)
   File "/usr/lib/python2.7/site-packages/vdsm/network/link/bond/sysfs_options_mapper.py", line 70, in _get_default_bonding_options
     with _bond_device(bond_name, mode):
   File "/usr/lib64/python2.7/contextlib.py", line 17, in __enter__
     return self.gen.next()
   File "/usr/lib/python2.7/site-packages/vdsm/network/link/bond/sysfs_options_mapper.py", line 103, in _bond_device
     _change_mode(bond_name, mode)
   File "/usr/lib/python2.7/site-packages/vdsm/network/link/bond/sysfs_options_mapper.py", line 114, in _change_mode
     opt.write(mode)
 IOError: [Errno 22] Invalid argument
 

The strace output shows that a write to the 'mode' sysfs file fails
with ERESTARTNOINTR, which triggers a system call restart. The second
call fails with EINVAL:


 open("/sys/class/net/bondscan-b5c6gn/bonding/mode", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 5
 fstat(5, {st_mode=S_IFREG|0644, st_size=4096, ...}) = 0
 fstat(5, {st_mode=S_IFREG|0644, st_size=4096, ...}) = 0
 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f14c8260000
 write(5, "1", 1)                        = ? ERESTARTNOINTR (To be restarted)
 write(5, "1", 1)                        = -1 EINVAL (Invalid argument)
 close(5)                                = 0


Running the attached systemtap script shows that the second write()
syscall has a wrong 'pos' argument (-513 instead of 1), which causes a
EINVAL error:


 ### (write '1' to 'mode' file)
 rw_verify_area: pos 0 count 1, ret 1 (vdsm-tool)
 bond_opt_tryset_rtnl: write option 0 value 1, ret -513 (vdsm-tool) <--- rtnl_lock busy
 bonding_sysfs_store_option: ret -513 (vdsm-tool)
 dev_attr_store: ret -513 (vdsm-tool)
 sysfs_kf_write: ret -513 (vdsm-tool)
 kernfs_fop_write: ret -513 (vdsm-tool)
 vfs_write: count 1 pos 0 file 0xffff8ae323a2a200 kernfs_fop_write, return -513 (vdsm-tool)
 ### (restarted syscall)
 rw_verify_area: pos -513 count 1, ret -22 (vdsm-tool)
 vfs_write: count 1 pos -513 file 0xffff8ae323a2a200 kernfs_fop_write, return -22 (vdsm-tool) <-- wrong pos


I suspect this is a bug in kernel.

Created attachment 1397870 [details]
strace output

Created attachment 1397871 [details]
Systemtap script

Created attachment 1397872 [details]
Systemtap output

Reassigning to kernel component for investigation...

The issue reproduced with 
3.10.0-829.el7.x86_64
3.10.0-830.el7.x86_64

I'd compare the strace above to a working case (just echo "1" > /sysfs/class/net/<ifc>/bonding/mode (or whatever the sysfs path is).  It looks to me like the problem is how vdsm is submitting the mode change:
write(5, "1", 1)
Thats the write call being made, and that looks to be a non-null terminated string (character length of 1), which is likely breaking the bonding option parsing code.  If you strace an echo call above, you will likely see the length is longer and an newline is included, which is what the bonding driver expects.

(In reply to Neil Horman from comment #16)
> I'd compare the strace above to a working case (just echo "1" >
> /sysfs/class/net/<ifc>/bonding/mode (or whatever the sysfs path is).  It
> looks to me like the problem is how vdsm is submitting the mode change:
> write(5, "1", 1)
> Thats the write call being made, and that looks to be a non-null terminated
> string (character length of 1), which is likely breaking the bonding option
> parsing code.  If you strace an echo call above, you will likely see the
> length is longer and an newline is included, which is what the bonding
> driver expects.

If you use echo, then it implicitly adds a newline ('\n'), the null termination is not sent in most cases.
strace sh -c "echo '1' > mode.txt" 2>&1 | grep write
write(1, "1\n", 2)

I do not think it is a requirement to pass a newline, especially that we always used it until now and only recently see a problem (which is not easy to recreate).

AFAIK, null termination is usually used internally by the language to detect the end of a string, I would not expect any back-end to require it, especially when by default it is not passed on as seen in the traces.

Almost nothing has changed in the bonding sysfs code for nearly two years, and this looks more like a core sysfs bug, nothing really bonding-specific. There was a sysfs namespace patchset that went into 828 though, the timing of which looks suspect to me, given that 829 is the first version where I see the bug reported (comment #15). Please try the most recent kernel that doesn't include commit b10eb5a72fd7de51ecadeea97e9921b0bf31cdc5 '[fs] sysfs: make attr namespace interface less convoluted' -- that looks to be kernel-3.10.0-827.el7.

The bug reproduced with kernel-3.10.0-830.el7 and reported against this kernel version

An easy reproducer:

----
#!/bin/sh

ip l add dummy1 type dummy
ip l add bond1 type bond
ip l add bond2 type bond

ip l set dummy1 master bond1
ip l set dummy1 up
ip l set bond1 up

while true; do cat /sys/class/net/bond1/bonding/slaves > /dev/null; done &

for i in $(seq 100000); do echo 2 > /sys/class/net/bond2/bonding/mode; done 
----

With kernel 3.10.0-830.el7.x86_64:
# ./rh1538630.sh
./rh1538630.sh: line 13: echo: write error: Invalid argument
./rh1538630.sh: line 13: echo: write error: Invalid argument
./rh1538630.sh: line 13: echo: write error: Invalid argument
./rh1538630.sh: line 13: echo: write error: Invalid argument
./rh1538630.sh: line 13: echo: write error: Invalid argument
./rh1538630.sh: line 13: echo: write error: Invalid argument
#


With kernel 3.10.0-843.el7.x86_64
# ./rh1538630.sh
#

The problem seems solved on recent kernels.

(In reply to Michael Burman from comment #19)
> The bug reproduced with kernel-3.10.0-830.el7 and reported against this
> kernel version

Yes, but I asked you to try a kernel from BEFORE this, to see if the patchset I referenced might be the cause of the regression. However, Beniamino is now saying that the problem appears to be resolved in even more recent kernels, so in that case, the bug can just be closed, no point in chasing our tails.

Based on comment #20, this is already fixed in the latest RHEL-7.5 development kernels.

What is the kernel version that resolves this issue? we currently have 3.10.0-851.el7.x86_64 latest available, does this version good for us?

(In reply to Michael Burman from comment #23)
> What is the kernel version that resolves this issue? we currently have
> 3.10.0-851.el7.x86_64 latest available, does this version good for us?

I don't know exactly what kernel resolved things, but if you read comment #20, you can see that Beniamino says it doesn't reproduce any longer on 843, so 851 is presumably also fine, but I'd suggest you test it to be certain.

I think this is a dupe of bug 1534483.

(In reply to Beniamino Galvani from comment #26)
> I think this is a dupe of bug 1534483.

Looks like it. In which case, the fix went into 837. Adjusting closed resolution to duplicate.

*** This bug has been marked as a duplicate of bug 1534483 ***