Re: [REGRESSION] ETXTBSY when running Yarn (Node) since af5d68f

Re: [REGRESSION] ETXTBSY when running Yarn (Node) since af5d68f

[Jens Axboe]

(removing stable as this isn't a stable regression, and the commit
itself isn't marked for stable to begin with).

On 5/21/24 10:02 AM, Andrew Udvare wrote:
> #regzbot introduced: v6.8..v6.9-rc1
> 
> https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git/commit/?id=af5d68f8892f8ee8f137648b79ceb2abc153a19b
> 
> Since the above commit present in 6.9+, Node running a Yarn installation that executes a subprocess always shows the following:
> 
> /test # yarn --offline install
> yarn install v1.22.22
> warning package.json: "test" is also the name of a node core module
> warning test@1.0.0: "test" is also the name of a node core module
> [1/4] Resolving packages...
> [2/4] Fetching packages...
> [3/4] Linking dependencies...
> [4/4] Building fresh packages...
> error /test/node_modules/snyk: Command failed.
> Exit code: 126
> Command: node wrapper_dist/bootstrap.js exec
> Arguments:
> Directory: /test/node_modules/snyk
> Output:
> /bin/sh: node: Text file busy
> 
> The commit was found by bisection with a simple initramfs that just runs 'yarn --offline install' with a test project and cached Yarn packages.
> 
> To reproduce:
> 
> npm install -g yarn
> mkdir test
> cd test
> cat > package.json <<EOF
> {
>    "name": "test",
>    "version": "1.0.0",
>    "main": "index.js",
>    "license": "MIT",
>    "dependencies": {
>      "snyk": "^1.1291.0"
>    }
> }
> EOF
> yarn install
> 
> Modern Yarn will give the same result but with slightly different output.
> 
> This also appears to affect node-gyp: https://github.com/nodejs/node/issues/53051
> 
> See also: https://bugs.gentoo.org/931942

This looks like a timing alteration due to task_work being done
differently, from a quick look and guess. For some reason SQPOLL is
being used. I tried running it here, but it doesn't reproduce for me.
Tried both current -git and 6.9 as released. I'll try on x86 as well to
see if I can hit it.

Maybe someone can describe what is happening here? I'm assuming that
something is racing with an io_uring operation done by SQPOLL, which is
keeping the file open until done.

This may or may not be a kernel issue, depending on what assumptions are
being made on when operations are begun and completed. Maybe those
assumptions are correct and there is indeed a kernel regression here, or
maybe the user side is just buggy in its assumptions.

-- 
Jens Axboe

Re: [REGRESSION] ETXTBSY when running Yarn (Node) since af5d68f

[Jens Axboe]

On 5/21/24 10:16 AM, Jens Axboe wrote:
> (removing stable as this isn't a stable regression, and the commit
> itself isn't marked for stable to begin with).
> 
> On 5/21/24 10:02 AM, Andrew Udvare wrote:
>> #regzbot introduced: v6.8..v6.9-rc1
>>
>> https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git/commit/?id=af5d68f8892f8ee8f137648b79ceb2abc153a19b
>>
>> Since the above commit present in 6.9+, Node running a Yarn installation that executes a subprocess always shows the following:
>>
>> /test # yarn --offline install
>> yarn install v1.22.22
>> warning package.json: "test" is also the name of a node core module
>> warning test@1.0.0: "test" is also the name of a node core module
>> [1/4] Resolving packages...
>> [2/4] Fetching packages...
>> [3/4] Linking dependencies...
>> [4/4] Building fresh packages...
>> error /test/node_modules/snyk: Command failed.
>> Exit code: 126
>> Command: node wrapper_dist/bootstrap.js exec
>> Arguments:
>> Directory: /test/node_modules/snyk
>> Output:
>> /bin/sh: node: Text file busy
>>
>> The commit was found by bisection with a simple initramfs that just runs 'yarn --offline install' with a test project and cached Yarn packages.
>>
>> To reproduce:
>>
>> npm install -g yarn
>> mkdir test
>> cd test
>> cat > package.json <<EOF
>> {
>>    "name": "test",
>>    "version": "1.0.0",
>>    "main": "index.js",
>>    "license": "MIT",
>>    "dependencies": {
>>      "snyk": "^1.1291.0"
>>    }
>> }
>> EOF
>> yarn install
>>
>> Modern Yarn will give the same result but with slightly different output.
>>
>> This also appears to affect node-gyp: https://github.com/nodejs/node/issues/53051
>>
>> See also: https://bugs.gentoo.org/931942
> 
> This looks like a timing alteration due to task_work being done
> differently, from a quick look and guess. For some reason SQPOLL is
> being used. I tried running it here, but it doesn't reproduce for me.
> Tried both current -git and 6.9 as released. I'll try on x86 as well to
> see if I can hit it.

Reproduces on an x86-64 vm:

[root@archlinux test]# yarn install 
yarn install v1.22.22
warning package.json: "test" is also the name of a node core module
info No lockfile found.
warning test@1.0.0: "test" is also the name of a node core module
[1/4] Resolving packages...
[2/4] Fetching packages...
[3/4] Linking dependencies...
[4/4] Building fresh packages...
error /root/test/node_modules/snyk: Command failed.
Exit code: 126
Command: node wrapper_dist/bootstrap.js exec
Arguments: 
Directory: /root/test/node_modules/snyk
Output:
/bin/sh: /tmp/yarn--1716308447842-0.8496252120161716/node: /bin/sh: bad interpreter: Text file busy

I'll poke a bit.

-- 
Jens Axboe

Re: [REGRESSION] ETXTBSY when running Yarn (Node) since af5d68f

[Christian Heusel]

[-- Attachment #1: Type: text/plain, Size: 1473 bytes --]

On 24/05/21 10:22AM, Jens Axboe wrote:
> > On 5/21/24 10:02 AM, Andrew Udvare wrote:
> >> #regzbot introduced: v6.8..v6.9-rc1
> >>
> >> https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git/commit/?id=af5d68f8892f8ee8f137648b79ceb2abc153a19b
> >>
> >> Since the above commit present in 6.9+, Node running a Yarn installation that executes a subprocess always shows the following:
> >>
> >> This also appears to affect node-gyp: https://github.com/nodejs/node/issues/53051
> >>
> >> See also: https://bugs.gentoo.org/931942
> > 
> > This looks like a timing alteration due to task_work being done
> > differently, from a quick look and guess. For some reason SQPOLL is
> > being used. I tried running it here, but it doesn't reproduce for me.
> > Tried both current -git and 6.9 as released. I'll try on x86 as well to
> > see if I can hit it.
> 

It seems like this also was a problem for libuv previously as somone
noted in a comment on the Arch Linux Bugtracker[0]:

- https://github.com/libuv/libuv/commit/1752791c9ea89dbf54e2a20a9d9f899119a2d179
- https://github.com/libuv/libuv/blob/v1.48.0/src/unix/linux.c#L834

Cheers,
Chris

[0]: https://gitlab.archlinux.org/archlinux/packaging/packages/linux/-/issues/55#note_186921

#regzbot introduced: af5d68f8892f8ee8f137648b79ceb2abc153a19b
#regzbot link: https://bugs.gentoo.org/931942
#regzbot link: https://gitlab.archlinux.org/archlinux/packaging/packages/linux/-/issues/55


[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: [REGRESSION] ETXTBSY when running Yarn (Node) since af5d68f

[Jens Axboe]

On 5/21/24 12:17 PM, Christian Heusel wrote:
> On 24/05/21 10:22AM, Jens Axboe wrote:
>>> On 5/21/24 10:02 AM, Andrew Udvare wrote:
>>>> #regzbot introduced: v6.8..v6.9-rc1
>>>>
>>>> https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git/commit/?id=af5d68f8892f8ee8f137648b79ceb2abc153a19b
>>>>
>>>> Since the above commit present in 6.9+, Node running a Yarn installation that executes a subprocess always shows the following:
>>>>
>>>> This also appears to affect node-gyp: https://github.com/nodejs/node/issues/53051
>>>>
>>>> See also: https://bugs.gentoo.org/931942
>>>
>>> This looks like a timing alteration due to task_work being done
>>> differently, from a quick look and guess. For some reason SQPOLL is
>>> being used. I tried running it here, but it doesn't reproduce for me.
>>> Tried both current -git and 6.9 as released. I'll try on x86 as well to
>>> see if I can hit it.
>>
> 
> It seems like this also was a problem for libuv previously as somone
> noted in a comment on the Arch Linux Bugtracker[0]:
> 
> - https://github.com/libuv/libuv/commit/1752791c9ea89dbf54e2a20a9d9f899119a2d179
> - https://github.com/libuv/libuv/blob/v1.48.0/src/unix/linux.c#L834

Just got that far in my local poking, it is indeed execve() getting
ETXTBUSY. I'll see if I can make a test case for this. Presumably the
application side is fine, eg it waits on the close completion before
doing the execve, not just having it be issued. Outside of that, only
other thing I can think of is that the final close would be punted to
task_work by fput(), which means there's also a dependency on the task
having run its kernel task_work before it's fully closed.

I'll be back with more info...

-- 
Jens Axboe

Re: [REGRESSION] ETXTBSY when running Yarn (Node) since af5d68f

[Jens Axboe]

On 5/21/24 12:25 PM, Jens Axboe wrote:
> Outside of that, only other thing I can think of is that the final
> close would be punted to task_work by fput(), which means there's also
> a dependency on the task having run its kernel task_work before it's
> fully closed.

Yep I think that's it, the below should fix it.


diff --git a/io_uring/sqpoll.c b/io_uring/sqpoll.c
index 554c7212aa46..68a3e3290411 100644
--- a/io_uring/sqpoll.c
+++ b/io_uring/sqpoll.c
@@ -241,6 +241,8 @@ static unsigned int io_sq_tw(struct llist_node **retry_list, int max_entries)
 			return count;
 		max_entries -= count;
 	}
+	if (task_work_pending(current))
+		task_work_run();
 
 	*retry_list = tctx_task_work_run(tctx, max_entries, &count);
 	return count;

-- 
Jens Axboe

Re: [REGRESSION] ETXTBSY when running Yarn (Node) since af5d68f

[Jens Axboe]

On 5/21/24 12:29 PM, Jens Axboe wrote:
> On 5/21/24 12:25 PM, Jens Axboe wrote:
>> Outside of that, only other thing I can think of is that the final
>> close would be punted to task_work by fput(), which means there's also
>> a dependency on the task having run its kernel task_work before it's
>> fully closed.
> 
> Yep I think that's it, the below should fix it.

Sent it out and also wrote a test case to catch this:

https://git.kernel.dk/cgit/liburing/commit/?id=06c22ef6637284ab1f31ee64f1ee48a829958816

just in case we ever regress in that manner again.

This will go into the 6.10-rc1 release, will ship it to Linus in a day or
two. And then it'll land in the next stable release of 6.9 as well.

Thanks for the report!

-- 
Jens Axboe

Re: [REGRESSION] ETXTBSY when running Yarn (Node) since af5d68f

[Christian Heusel]

[-- Attachment #1: Type: text/plain, Size: 537 bytes --]

On 24/05/21 12:29PM, Jens Axboe wrote:
> On 5/21/24 12:25 PM, Jens Axboe wrote:
> > Outside of that, only other thing I can think of is that the final
> > close would be punted to task_work by fput(), which means there's also
> > a dependency on the task having run its kernel task_work before it's
> > fully closed.
> 
> Yep I think that's it, the below should fix it.

It indeed does! I applied the patch on top of Linus tree and the issue
is now gone!

Tested-by: Christian Heusel <christian@heusel.eu>

Cheers,
Chris

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: [REGRESSION] ETXTBSY when running Yarn (Node) since af5d68f

[Jens Axboe]

On 5/21/24 1:07 PM, Christian Heusel wrote:
> On 24/05/21 12:29PM, Jens Axboe wrote:
>> On 5/21/24 12:25 PM, Jens Axboe wrote:
>>> Outside of that, only other thing I can think of is that the final
>>> close would be punted to task_work by fput(), which means there's also
>>> a dependency on the task having run its kernel task_work before it's
>>> fully closed.
>>
>> Yep I think that's it, the below should fix it.
> 
> It indeed does! I applied the patch on top of Linus tree and the issue
> is now gone!
> 
> Tested-by: Christian Heusel <christian@heusel.eu>

Thanks for testing! I'll add your tag.

-- 
Jens Axboe

Re: [REGRESSION] ETXTBSY when running Yarn (Node) since af5d68f

[Andrew Udvare]

[-- Attachment #1.1: Type: text/plain, Size: 1374 bytes --]

On 21/05/2024 14:29, Jens Axboe wrote:
> On 5/21/24 12:25 PM, Jens Axboe wrote:
>> Outside of that, only other thing I can think of is that the final
>> close would be punted to task_work by fput(), which means there's also
>> a dependency on the task having run its kernel task_work before it's
>> fully closed.
> 
> Yep I think that's it, the below should fix it.
> 
> 
> diff --git a/io_uring/sqpoll.c b/io_uring/sqpoll.c
> index 554c7212aa46..68a3e3290411 100644
> --- a/io_uring/sqpoll.c
> +++ b/io_uring/sqpoll.c
> @@ -241,6 +241,8 @@ static unsigned int io_sq_tw(struct llist_node **retry_list, int max_entries)
>   			return count;
>   		max_entries -= count;
>   	}
> +	if (task_work_pending(current))
> +		task_work_run();
>   
>   	*retry_list = tctx_task_work_run(tctx, max_entries, &count);
>   	return count;
> 

This patch works for me on 6.9.1.

  $ yarn
yarn install v1.22.22
warning package.json: "test" is also the name of a node core module
info No lockfile found.
warning test@1.0.0: "test" is also the name of a node core module
[1/4] Resolving packages...
[2/4] Fetching packages...
[3/4] Linking dependencies...
[4/4] Building fresh packages...
success Saved lockfile.
Done in 3.32s.

  $ uname -a
Linux limelight 6.9.1-gentoo-limelight #2 SMP PREEMPT_DYNAMIC TKG Tue 
May 21 15:21:33 EDT 2024

--
Andrew

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 840 bytes --]

Re: [REGRESSION] ETXTBSY when running Yarn (Node) since af5d68f

[Jens Axboe]

On 5/21/24 1:30 PM, Andrew Udvare wrote:
> On 21/05/2024 14:29, Jens Axboe wrote:
>> On 5/21/24 12:25 PM, Jens Axboe wrote:
>>> Outside of that, only other thing I can think of is that the final
>>> close would be punted to task_work by fput(), which means there's also
>>> a dependency on the task having run its kernel task_work before it's
>>> fully closed.
>>
>> Yep I think that's it, the below should fix it.
>>
>>
>> diff --git a/io_uring/sqpoll.c b/io_uring/sqpoll.c
>> index 554c7212aa46..68a3e3290411 100644
>> --- a/io_uring/sqpoll.c
>> +++ b/io_uring/sqpoll.c
>> @@ -241,6 +241,8 @@ static unsigned int io_sq_tw(struct llist_node **retry_list, int max_entries)
>>               return count;
>>           max_entries -= count;
>>       }
>> +    if (task_work_pending(current))
>> +        task_work_run();
>>         *retry_list = tctx_task_work_run(tctx, max_entries, &count);
>>       return count;
>>
> 
> This patch works for me on 6.9.1.
> 
>  $ yarn
> yarn install v1.22.22
> warning package.json: "test" is also the name of a node core module
> info No lockfile found.
> warning test@1.0.0: "test" is also the name of a node core module
> [1/4] Resolving packages...
> [2/4] Fetching packages...
> [3/4] Linking dependencies...
> [4/4] Building fresh packages...
> success Saved lockfile.
> Done in 3.32s.
> 
>  $ uname -a
> Linux limelight 6.9.1-gentoo-limelight #2 SMP PREEMPT_DYNAMIC TKG Tue May 21 15:21:33 EDT 2024

Great, thank you for testing!

-- 
Jens Axboe

Re: [REGRESSION] ETXTBSY when running Yarn (Node) since af5d68f

[Andrew Udvare]

[-- Attachment #1.1: Type: text/plain, Size: 422 bytes --]

On 21/05/2024 14:29, Jens Axboe wrote:
> On 5/21/24 12:25 PM, Jens Axboe wrote:
>> Outside of that, only other thing I can think of is that the final
>> close would be punted to task_work by fput(), which means there's also
>> a dependency on the task having run its kernel task_work before it's
>> fully closed.
> 
> Yep I think that's it, the below should fix it.

Tested-by: Andrew Udvare <audvare@gmail.com>

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 840 bytes --]

Re: [REGRESSION] ETXTBSY when running Yarn (Node) since af5d68f

[Jens Axboe]

On 5/21/24 1:33 PM, Andrew Udvare wrote:
> On 21/05/2024 14:29, Jens Axboe wrote:
>> On 5/21/24 12:25 PM, Jens Axboe wrote:
>>> Outside of that, only other thing I can think of is that the final
>>> close would be punted to task_work by fput(), which means there's also
>>> a dependency on the task having run its kernel task_work before it's
>>> fully closed.
>>
>> Yep I think that's it, the below should fix it.
> 
> Tested-by: Andrew Udvare <audvare@gmail.com>

Added, thanks.

-- 
Jens Axboe