Re: process killed: text file modification

On 2017. 03. 09. 20:47, Gergely Czuczy wrote:
>
>
> On 2017. 03. 09. 19:44, John Baldwin wrote:
>> On Thursday, March 09, 2017 03:31:56 PM Gergely Czuczy wrote:
>>> [+freebsd-fs]
>>>
>>>
>>> On 2017. 03. 09. 14:20, Gergely Czuczy wrote:
>>>> On 2017. 03. 09. 11:27, Gergely Czuczy wrote:
>>>>> Hello,
>>>>>
>>>>> I'm trying to build a few things from ports on an rpi3, the ports
>>>>> collection is mounted over NFS from another machine. When it's trying
>>>>> to build pkg i'm getting the error message in syslog:
>>>>>
>>>>> rpi3 kernel: pid 4451 (sh), uid 0, was killed: text file modification
>>>>>
>>>>> The report to pkg_at_:
>>>>> https://lists.freebsd.org/pipermail/freebsd-pkg/2017-March/002048.html 
>>>>>
>>>>>
>>>>> In ports-mgmt/pkg's config.log It fails at the following entry:
>>>>> configure:3726: checking whether we are cross compiling
>>>>> configure:3734: cc -o conftest -O2 -pipe  -Wno-error
>>>>> -fno-strict-aliasing   conftest.c  >&5
>>>>> configure:3738: $? = 0
>>>>> configure:3745: ./conftest
>>>>> configure:3749: $? = 137
>>>>> configure:3756: error: in 
>>>>> `/usr/ports/ports-mgmt/pkg/work/pkg-1.10.0':
>>>>> configure:3760: error: cannot run C compiled programs.
>>>>> If you meant to cross compile, use `--host'.
>>>>> See `config.log' for more details
>>>>>
>>>>> # uname -a
>>>>> FreeBSD rpi3 12.0-CURRENT FreeBSD 12.0-CURRENT #0 r314949: Thu Mar 9
>>>>> 08:58:46 CET 2017
>>>>> aegir_at_marvin.harmless.hu:/tank/rpi3/crochet/work/obj/arm64.aarch64/tank/rpi3/src/sys/AEGIR 
>>>>>
>>>>> arm64
>>>> So far, a few additions:
>>>> Time is synced between the NFS server and the client.
>>>> it's an open() call which is getting the kill, and it's not the file
>>>> what's being opened, but the process executing it.
>>>> Here's a simple code that reproduces it:
>>>> #include <stdio.h>
>>>>
>>>> int main() {
>>>>
>>>>    FILE *f = fopen ("/bar", "w");
>>>>
>>>>    fclose(f);
>>>>    return 0;
>>>> }
>>>>
>>>> Conditions to reproduce it:
>>>>   - The resulting binary must be executed from the nfs mount
>>>>   - The binary must be built after mounting the NFS share.
>>>>
>>>> I haven't tried building it on a different host, I don't have access
>>>> to multiple RPis. Also, if I build the binary, umount/remount the NFS
>>>> mount point, which has the binary, execute it, then it works.
>>>>
>>>> I've also tried this with the raspbsd.org's image, I could reproduce
>>>> it as well.
>>>>
>>>> Another interesting thing is, when I first booted the RPi up, the NFS
>>>> server was a 10.2-STABLE, and later got updated to 11-STABLE. While it
>>>> was 10.2 I've tried to build some port, and I don't remember having
>>>> this issue.
>>>>
>>>> So, could someone please help me figure this out and fix it? This
>>>> stuff should work pretty much.
>>>>
>>> So, this error message comes from here:
>>> https://svnweb.freebsd.org/base/head/sys/fs/nfsclient/nfs_clbio.c?revision=314436&view=markup#l1674 
>>>
>>>
>>> It's the NFS_TIMESPEC_COMPARE(&np->n_mtime, &np->n_vattr.na_mtime)
>>> comparision that fails, np should be the NFS node structure, from the
>>> vnode's v_data, and n_vattr is the attribute cache. As I've seen these
>>> two are being updated together, so I don't really see by the code why
>>> they might differ. Could someone please take a look at it, with more
>>> experience in the NFS code? -czg
>> Can you print out the two mtimes?  I wonder if what's happening is that
>> your server uses different granularity (for example just seconds) than
>> your client, so on the client we generate a timestamp with a non-zero
>> nanoseconds but when the server receives that timestamp it "truncates"
>> it.  During open() we forcefully re-fetch the timestamp (for CTO
>> consistency) and then notice it doesn't match.  For now I would start
>> with comparing the timestamps and maybe the vfs.timestamp_precision
>> sysctls on client and server (if server is a FreeBSD box).
> Here are the time values:
> Mar  9 19:46:01 rpi3 kernel: np->n_mtime: -3298114786344 + 
> -3298114786336  &np->n_vattr.na_mtime: -3298114786616 + -3298114786608
> Mar  9 19:46:01 rpi3 kernel: pid 912 (csh), uid 0, was killed: text 
> file modification
> Mar  9 19:46:01 rpi3 kernel: np->n_mtime: -3298114786344 + 
> -3298114786336  &np->n_vattr.na_mtime: -3298114786616 + -3298114786608
> Mar  9 19:46:01 rpi3 kernel: pid 912 (csh), uid 0, was killed: text 
> file modification
>
> Printed this way:
>                          printf("np->n_mtime: %ji + %ji 
> &np->n_vattr.na_mtime: %ji + %ji",
> (intmax_t)(&np->n_mtime.tv_sec),
> (intmax_t)(&np->n_mtime.tv_nsec),
> (intmax_t)(&np->n_vattr.na_mtime.tv_sec),
> (intmax_t)(&np->n_vattr.na_mtime.tv_nsec));
Sorry, I made a typo there. Here's it now:
Mar  9 20:05:35 rpi3 kernel: np->n_mtime: 1489089935 + 219323000 
&np->n_vattr.na_mtime: 1489089935 + 221438000
Mar  9 20:05:35 rpi3 kernel: pid 847 (csh), uid 0, was killed: text file 
modification
Mar  9 20:05:35 rpi3 kernel: np->n_mtime: 1489089935 + 219323000 
&np->n_vattr.na_mtime: 1489089935 + 221438000
Mar  9 20:05:35 rpi3 kernel: pid 847 (csh), uid 0, was killed: text file 
modification

That's a difference of 2115 micro seconds.