[RFC] util: shutdown log in cr_system_userns if error fd is negative

Submitted by Stanislav Kinsburskiy on April 22, 2016, 10:20 a.m.

Details

Message ID 20160422102052.83186.65287.stgit@skinsbursky-vz7.qa.sw.ru
State Accepted
Series "util: shutdown log in cr_system_userns if error fd is negative"
Commit 1dc2f87b33ce4263a031512d1e04421de5db979e
Headers show

Patch hide | download patch | download mbox

diff --git a/criu/util.c b/criu/util.c
index 4f88309..dae6031 100644
--- a/criu/util.c
+++ b/criu/util.c
@@ -609,6 +609,8 @@  int cr_system_userns(int in, int out, int err, char *cmd,
 		pr_perror("fork() failed");
 		goto out;
 	} else if (pid == 0) {
+		bool stop_log_fd = false;
+
 		if (userns_pid > 0) {
 			if (switch_ns(userns_pid, &user_ns_desc, NULL))
 				goto out_chld;
@@ -620,8 +622,10 @@  int cr_system_userns(int in, int out, int err, char *cmd,
 
 		if (out < 0)
 			out = log_get_fd();
-		if (err < 0)
+		if (err < 0) {
 			err = log_get_fd();
+			stop_log_fd = true;
+		}
 
 		/*
 		 * out, err, in should be a separate fds,
@@ -637,6 +641,9 @@  int cr_system_userns(int in, int out, int err, char *cmd,
 		    move_img_fd(&err, STDIN_FILENO))
 			goto out_chld;
 
+		if (stop_log_fd)
+			log_fini();
+
 		if (in < 0) {
 			close(STDIN_FILENO);
 		} else {

Comments

Pavel Emelianov April 22, 2016, 1:53 p.m.
On 04/22/2016 01:20 PM, Stanislav Kinsburskiy wrote:
> Otherwise error in case of exec error won't be printed
> The problem is that when err fd is negative, it's replaced by log fd.
> Then err is moved to STDERR (that means, that log_fd is _closed_).

Why, log fd is service fd, not STDERR one.

> But log facility still consider log fd as valid and tries to use it to print
> error message in case of exec failure.
> Which is equal to writing to /dev/null, basically.
> This patch shutdown log, if err fd was negative, thus forcing criu to output
> exec error to STDERR (which was replaced by log fs, btw).

Not necessarily it's replaced by logfd, err can be specified.

> 
> Signed-off-by: Stanislav Kinsburskiy <skinsbursky@virtuozzo.com>
> ---
>  criu/util.c |    9 ++++++++-
>  1 file changed, 8 insertions(+), 1 deletion(-)
> 
> diff --git a/criu/util.c b/criu/util.c
> index 4f88309..dae6031 100644
> --- a/criu/util.c
> +++ b/criu/util.c
> @@ -609,6 +609,8 @@ int cr_system_userns(int in, int out, int err, char *cmd,
>  		pr_perror("fork() failed");
>  		goto out;
>  	} else if (pid == 0) {
> +		bool stop_log_fd = false;
> +
>  		if (userns_pid > 0) {
>  			if (switch_ns(userns_pid, &user_ns_desc, NULL))
>  				goto out_chld;
> @@ -620,8 +622,10 @@ int cr_system_userns(int in, int out, int err, char *cmd,
>  
>  		if (out < 0)
>  			out = log_get_fd();
> -		if (err < 0)
> +		if (err < 0) {
>  			err = log_get_fd();
> +			stop_log_fd = true;
> +		}
>  
>  		/*
>  		 * out, err, in should be a separate fds,
> @@ -637,6 +641,9 @@ int cr_system_userns(int in, int out, int err, char *cmd,
>  		    move_img_fd(&err, STDIN_FILENO))
>  			goto out_chld;
>  
> +		if (stop_log_fd)
> +			log_fini();
> +
>  		if (in < 0) {
>  			close(STDIN_FILENO);
>  		} else {
> 
> _______________________________________________
> CRIU mailing list
> CRIU@openvz.org
> https://lists.openvz.org/mailman/listinfo/criu
> .
>
Stanislav Kinsburskiy April 22, 2016, 1:58 p.m.
22.04.2016 15:53, Pavel Emelyanov пишет:
> On 04/22/2016 01:20 PM, Stanislav Kinsburskiy wrote:
>> Otherwise error in case of exec error won't be printed
>> The problem is that when err fd is negative, it's replaced by log fd.
>> Then err is moved to STDERR (that means, that log_fd is _closed_).
> Why, log fd is service fd, not STDERR one.

Not sure I got it correctly.
There is an error message below the mentioned hunk:

pr_perror("exec failed");

In case err_fd is passes as "-1", this message will be never printed.
Because:
1) err = log_fd();
2) err copied to STDERR and then closed (log_fd is actually closed)

Then in case of error criu tries to write to log_fd, because its service 
fd bit is still set ===> Write fails.


>> But log facility still consider log fd as valid and tries to use it to print
>> error message in case of exec failure.
>> Which is equal to writing to /dev/null, basically.
>> This patch shutdown log, if err fd was negative, thus forcing criu to output
>> exec error to STDERR (which was replaced by log fs, btw).
> Not necessarily it's replaced by logfd, err can be specified.

That's why stop_log_fd is used

>> Signed-off-by: Stanislav Kinsburskiy <skinsbursky@virtuozzo.com>
>> ---
>>   criu/util.c |    9 ++++++++-
>>   1 file changed, 8 insertions(+), 1 deletion(-)
>>
>> diff --git a/criu/util.c b/criu/util.c
>> index 4f88309..dae6031 100644
>> --- a/criu/util.c
>> +++ b/criu/util.c
>> @@ -609,6 +609,8 @@ int cr_system_userns(int in, int out, int err, char *cmd,
>>   		pr_perror("fork() failed");
>>   		goto out;
>>   	} else if (pid == 0) {
>> +		bool stop_log_fd = false;
>> +
>>   		if (userns_pid > 0) {
>>   			if (switch_ns(userns_pid, &user_ns_desc, NULL))
>>   				goto out_chld;
>> @@ -620,8 +622,10 @@ int cr_system_userns(int in, int out, int err, char *cmd,
>>   
>>   		if (out < 0)
>>   			out = log_get_fd();
>> -		if (err < 0)
>> +		if (err < 0) {
>>   			err = log_get_fd();
>> +			stop_log_fd = true;
>> +		}
>>   
>>   		/*
>>   		 * out, err, in should be a separate fds,
>> @@ -637,6 +641,9 @@ int cr_system_userns(int in, int out, int err, char *cmd,
>>   		    move_img_fd(&err, STDIN_FILENO))
>>   			goto out_chld;
>>   
>> +		if (stop_log_fd)
>> +			log_fini();
>> +
>>   		if (in < 0) {
>>   			close(STDIN_FILENO);
>>   		} else {
>>
>> _______________________________________________
>> CRIU mailing list
>> CRIU@openvz.org
>> https://lists.openvz.org/mailman/listinfo/criu
>> .
>>
Pavel Emelianov April 22, 2016, 2:37 p.m.
On 04/22/2016 04:58 PM, Stanislav Kinsburskiy wrote:
> 
> 
> 22.04.2016 15:53, Pavel Emelyanov пишет:
>> On 04/22/2016 01:20 PM, Stanislav Kinsburskiy wrote:
>>> Otherwise error in case of exec error won't be printed
>>> The problem is that when err fd is negative, it's replaced by log fd.
>>> Then err is moved to STDERR (that means, that log_fd is _closed_).
>> Why, log fd is service fd, not STDERR one.
> 
> Not sure I got it correctly.
> There is an error message below the mentioned hunk:
> 
> pr_perror("exec failed");
> 
> In case err_fd is passes as "-1", this message will be never printed.
> Because:
> 1) err = log_fd();
> 2) err copied to STDERR and then closed (log_fd is actually closed)
> 
> Then in case of error criu tries to write to log_fd, because its service 
> fd bit is still set ===> Write fails.

Ah, I see. Patch applied, thanks.
Andrey Vagin April 22, 2016, 4:19 p.m.
=== Run 1/1 ================

====================== Run zdtm/static/binfmt_misc in ns =======================
Start test
Test is SUID
./binfmt_misc --pidfile=binfmt_misc.pid --outfile=binfmt_misc.out --dirname=binfmt_misc.dir.test --filename=binfmt_misc.test
Run criu dump
(00.002492) Error (util.c:210): Dup 1023 -> 1 failed (called at util.c:657): Bad file descriptor
(00.002864) Error (util.c:210): Dup 1023 -> 1 failed (called at util.c:657): Bad file descriptor
(00.003257) Error (util.c:210): Dup 1023 -> 1 failed (called at util.c:657): Bad file descriptor
(00.003570) Error (util.c:210): Dup 1023 -> 1 failed (called at util.c:657): Bad file descriptor
=[log]=> dump/zdtm/static/binfmt_misc/31/1/dump.log
------------------------ grep Error ------------------------
(00.002637) Error (util.c:679): exited, status=1
(00.003026) Error (util.c:679): exited, status=1
(00.003379) Error (util.c:679): exited, status=1
(00.003679) Error (util.c:679): exited, status=1
(00.003739) Error (cr-dump.c:1614): Dumping FAILED.
------------------------ ERROR OVER ------------------------
################ Test zdtm/static/binfmt_misc FAIL at CRIU dump ################
Wait for zdtm/static/binfmt_misc to die for 0.100000
##################################### FAIL #####################################


On Fri, Apr 22, 2016 at 01:20:55PM +0300, Stanislav Kinsburskiy wrote:
> Otherwise error in case of exec error won't be printed
> The problem is that when err fd is negative, it's replaced by log fd.
> Then err is moved to STDERR (that means, that log_fd is _closed_).
> But log facility still consider log fd as valid and tries to use it to print
> error message in case of exec failure.
> Which is equal to writing to /dev/null, basically.
> This patch shutdown log, if err fd was negative, thus forcing criu to output
> exec error to STDERR (which was replaced by log fs, btw).
> 
> Signed-off-by: Stanislav Kinsburskiy <skinsbursky@virtuozzo.com>
> ---
>  criu/util.c |    9 ++++++++-
>  1 file changed, 8 insertions(+), 1 deletion(-)
> 
> diff --git a/criu/util.c b/criu/util.c
> index 4f88309..dae6031 100644
> --- a/criu/util.c
> +++ b/criu/util.c
> @@ -609,6 +609,8 @@ int cr_system_userns(int in, int out, int err, char *cmd,
>  		pr_perror("fork() failed");
>  		goto out;
>  	} else if (pid == 0) {
> +		bool stop_log_fd = false;
> +
>  		if (userns_pid > 0) {
>  			if (switch_ns(userns_pid, &user_ns_desc, NULL))
>  				goto out_chld;
> @@ -620,8 +622,10 @@ int cr_system_userns(int in, int out, int err, char *cmd,
>  
>  		if (out < 0)
>  			out = log_get_fd();
> -		if (err < 0)
> +		if (err < 0) {
>  			err = log_get_fd();
> +			stop_log_fd = true;
> +		}
>  
>  		/*
>  		 * out, err, in should be a separate fds,
> @@ -637,6 +641,9 @@ int cr_system_userns(int in, int out, int err, char *cmd,
>  		    move_img_fd(&err, STDIN_FILENO))
>  			goto out_chld;
>  
> +		if (stop_log_fd)
> +			log_fini();
> +
>  		if (in < 0) {
>  			close(STDIN_FILENO);
>  		} else {
> 
> _______________________________________________
> CRIU mailing list
> CRIU@openvz.org
> https://lists.openvz.org/mailman/listinfo/criu
Andrey Vagin April 22, 2016, 4:21 p.m.
On Fri, Apr 22, 2016 at 05:37:40PM +0300, Pavel Emelyanov wrote:
> On 04/22/2016 04:58 PM, Stanislav Kinsburskiy wrote:
> > 
> > 
> > 22.04.2016 15:53, Pavel Emelyanov пишет:
> >> On 04/22/2016 01:20 PM, Stanislav Kinsburskiy wrote:
> >>> Otherwise error in case of exec error won't be printed
> >>> The problem is that when err fd is negative, it's replaced by log fd.
> >>> Then err is moved to STDERR (that means, that log_fd is _closed_).
> >> Why, log fd is service fd, not STDERR one.
> > 
> > Not sure I got it correctly.
> > There is an error message below the mentioned hunk:
> > 
> > pr_perror("exec failed");
> > 
> > In case err_fd is passes as "-1", this message will be never printed.
> > Because:
> > 1) err = log_fd();
> > 2) err copied to STDERR and then closed (log_fd is actually closed)
> > 
> > Then in case of error criu tries to write to log_fd, because its service 
> > fd bit is still set ===> Write fails.
> 
> Ah, I see. Patch applied, thanks.

Pls, don't commit patches which fails validation

https://zdtm.openvz.org/series/26/

> 
> _______________________________________________
> CRIU mailing list
> CRIU@openvz.org
> https://lists.openvz.org/mailman/listinfo/criu