2132978 – Direct Volume Migration is failing as rsync pod on source cluster goes into "Error" state

Bug 2132978 - Direct Volume Migration is failing as rsync pod on source cluster goes into "Error" state

Summary: Direct Volume Migration is failing as rsync pod on source cluster goes into "...

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Migration Toolkit for Containers
Classification:	Red Hat
Component:	General
Sub Component:
Version:	1.7.5
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	urgent
Target Milestone:	---
Target Release:	1.7.5
Assignee:	Pranav Gaikwad
QA Contact:	ssingla
Docs Contact:	Anjana Suparna Sriram
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2022-10-07 11:56 UTC by ssingla
Modified:	2022-10-31 11:10 UTC (History)
CC List:	2 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2022-10-31 11:10:35 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)
Migration Page Screenshot (128.39 KB, image/png) 2022-10-07 11:56 UTC, ssingla	no flags	Details
View All

Links
System	ID	Priority	Status	Summary	Last Updated
Github	migtools mig-controller pull 1314	None	Merged	Bug 2132978: don't change security context if psa is not enforced	2022-10-12 12:32:38 UTC
Github	migtools mig-controller pull 1316	None	Merged	Bug 2132978: don't change security context if psa is not enforced (#1314)	2022-10-10 13:30:09 UTC
Github	migtools mig-controller pull 1318	None	Merged	add lost+found to excluded files (#1317)	2022-10-17 19:25:24 UTC
Github	migtools mig-controller pull 1319	None	Merged	Copy labels from source namespaces	2022-10-19 18:58:37 UTC
Github	migtools mig-controller pull 1320	None	Merged	copy labels from source namespaces (#1319)	2022-10-19 18:58:37 UTC
Red Hat Product Errata	RHBA-2022:7262	None	None	None	2022-10-31 11:10:40 UTC

Description ssingla 2022-10-07 11:56:33 UTC

Created attachment 1916704 [details]
Migration Page Screenshot

Description of problem:
On migrating any application with PVC, migration shows Succeeded with warnings, with DVM status as failed after 20 rsync retries.

Version-Release number of selected component (if applicable):
OCP 4.11 - Target
OCP 4.6 - Source

How reproducible:
Always

Steps to Reproduce:
1.Deploy any basic application with PVC on the source cluster.
2.Login to MTC UI and create a migration plan with Full migration selected.
3. Run the Cutover migration.

Actual results:
Migration succeeds with warnings and Direct Volume Migration fails with rsync pod on source namespace going into error state.

Expected results:
Migration with DVM should be successful.

Additional info:

Source Namespace pods:

$ oc get pods -n ocp-robot-shop
NAME                         READY   STATUS              RESTARTS   AGE
cart-7cffd844db-qx9l4        1/1     Running             0          8m38s
catalogue-6bd7b6664c-gh8mj   1/1     Running             0          8m38s
dispatch-5f454ff45-bs6xq     1/1     Running             0          8m38s
mongodb-56d8597f95-9ts5n     1/1     Running             0          8m38s
mysql-1-deploy               0/1     Completed           0          8m37s
mysql-1-mx57c                1/1     Running             0          8m35s
payment-6687bf86f9-h28zd     1/1     Running             0          8m37s
rabbitmq-75d9cf4484-6p9vc    1/1     Running             0          8m37s
ratings-f89477654-gxvlv      1/1     Running             0          8m37s
redis-75fd75d7fb-lb9fd       1/1     Running             0          8m37s
rsync-46gxf                  0/2     ContainerCreating   0          3s
rsync-gmjjq                  0/2     Error               0          8s
rsync-hrxds                  0/2     Error               0          6s
shipping-56ff6d5d66-m2dkj    1/1     Running             0          8m37s
user-5b8cf58f99-5g85j        1/1     Running             0          8m36s
web-6c9685f5b8-sjvrh         1/1     Running             0          8m36s

Rsync logs:


: Service [rsync] finished (0 left)
2022/10/07 11:48:08 [54] building file list
sending incremental file list
2022/10/07 11:48:08 [54] rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/cities" failed: Permission denied (13)
2022/10/07 11:48:08 [54] rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/lost+found" failed: Permission denied (13)
2022/10/07 11:48:08 [54] rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/mysql" failed: Permission denied (13)
rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/cities" failed: Permission denied (13)
rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/lost+found" failed: Permission denied (13)
rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/mysql" failed: Permission denied (13)
rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/performance_schema" failed: Permission denied (13)
rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/ratings" failed: Permission denied (13)
2022/10/07 11:48:08 [54] rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/performance_schema" failed: Permission denied (13)
2022/10/07 11:48:08 [54] rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/ratings" failed: Permission denied (13)
2022/10/07 11:48:08 [54] rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/sys" failed: Permission denied (13)
rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/sys" failed: Permission denied (13)

Comment 1 ssingla 2022-10-07 11:58:13 UTC

Attaching rsync pod logs

$ oc logs -n ocp-robot-shop rsync-46gxf --all-containers
2022.10.07 11:48:08 LOG5[ui]: stunnel 5.56 on x86_64-redhat-linux-gnu platform
2022.10.07 11:48:08 LOG5[ui]: Compiled with OpenSSL 1.1.1g FIPS  21 Apr 2020
2022.10.07 11:48:08 LOG5[ui]: Running  with OpenSSL 1.1.1k  FIPS 25 Mar 2021
2022.10.07 11:48:08 LOG5[ui]: Threading:PTHREAD Sockets:POLL,IPv6 TLS:ENGINE,FIPS,OCSP,PSK,SNI
2022.10.07 11:48:08 LOG5[ui]: Reading configuration from file /etc/stunnel/stunnel.conf
2022.10.07 11:48:08 LOG5[ui]: UTF-8 byte order mark not detected
2022.10.07 11:48:08 LOG5[ui]: FIPS mode disabled
2022.10.07 11:48:08 LOG4[ui]: Insecure file permissions on /etc/stunnel/certs/tls.key
2022.10.07 11:48:08 LOG4[ui]: Service [rsync] needs authentication to prevent MITM attacks
2022.10.07 11:48:08 LOG5[ui]: Configuration successful
2022.10.07 11:48:08 LOG5[ui]: Binding service [rsync] to :::6443: Address already in use (98)
2022.10.07 11:48:08 LOG7[0]: Service [rsync] started
2022.10.07 11:48:08 LOG7[0]: Setting local socket options (FD=3)
2022.10.07 11:48:08 LOG7[0]: Option TCP_NODELAY set on local socket
2022.10.07 11:48:08 LOG5[0]: Service [rsync] accepted connection from 127.0.0.1:55346
2022.10.07 11:48:08 LOG6[0]: s_connect: connecting 35.239.37.21:443
2022.10.07 11:48:08 LOG7[0]: s_connect: s_poll_wait 35.239.37.21:443: waiting 10 seconds
2022.10.07 11:48:08 LOG7[0]: FD=6 events=0x2001 revents=0x0
2022.10.07 11:48:08 LOG7[0]: FD=10 events=0x2005 revents=0x0
2022.10.07 11:48:08 LOG5[0]: s_connect: connected 35.239.37.21:443
2022.10.07 11:48:08 LOG5[0]: Service [rsync] connected remote server from 10.130.2.57:36478
2022.10.07 11:48:08 LOG7[0]: Setting remote socket options (FD=10)
2022.10.07 11:48:08 LOG7[0]: Option TCP_NODELAY set on remote socket
2022.10.07 11:48:08 LOG7[0]: Remote descriptor (FD=10) initialized
2022.10.07 11:48:08 LOG6[0]: SNI: sending servername: dvm-ocp-robot-shop.apps.cam-tgt-46330.qe.gcp.devcluster.openshift.com
2022.10.07 11:48:08 LOG6[0]: Peer certificate not required
2022.10.07 11:48:08 LOG7[0]: TLS state (connect): before SSL initialization
2022.10.07 11:48:08 LOG7[0]: Initializing application specific data for session authenticated
2022.10.07 11:48:08 LOG7[0]: TLS state (connect): SSLv3/TLS write client hello
2022.10.07 11:48:08 LOG7[1]: Service [rsync] started
2022.10.07 11:48:08 LOG7[1]: Setting local socket options (FD=11)
2022.10.07 11:48:08 LOG7[1]: Option TCP_NODELAY set on local socket
2022.10.07 11:48:08 LOG5[1]: Service [rsync] accepted connection from 127.0.0.1:55354
2022.10.07 11:48:08 LOG6[1]: s_connect: connecting 35.239.37.21:443
2022.10.07 11:48:08 LOG7[1]: s_connect: s_poll_wait 35.239.37.21:443: waiting 10 seconds
2022.10.07 11:48:08 LOG7[1]: FD=6 events=0x2001 revents=0x0
2022.10.07 11:48:08 LOG7[1]: FD=12 events=0x2005 revents=0x0
2022.10.07 11:48:08 LOG5[1]: s_connect: connected 35.239.37.21:443
2022.10.07 11:48:08 LOG5[1]: Service [rsync] connected remote server from 10.130.2.57:36486
2022.10.07 11:48:08 LOG7[1]: Setting remote socket options (FD=12)
2022.10.07 11:48:08 LOG7[1]: Option TCP_NODELAY set on remote socket
2022.10.07 11:48:08 LOG7[1]: Remote descriptor (FD=12) initialized
2022.10.07 11:48:08 LOG6[1]: SNI: sending servername: dvm-ocp-robot-shop.apps.cam-tgt-46330.qe.gcp.devcluster.openshift.com
2022.10.07 11:48:08 LOG6[1]: Peer certificate not required
2022.10.07 11:48:08 LOG7[1]: TLS state (connect): before SSL initialization
2022.10.07 11:48:08 LOG7[1]: Initializing application specific data for session authenticated
2022.10.07 11:48:08 LOG7[1]: TLS state (connect): SSLv3/TLS write client hello
2022.10.07 11:48:08 LOG7[0]: TLS state (connect): SSLv3/TLS write client hello
2022.10.07 11:48:08 LOG7[0]: TLS state (connect): SSLv3/TLS read server hello
2022.10.07 11:48:08 LOG6[0]: Certificate verification disabled
2022.10.07 11:48:08 LOG6[0]: Certificate verification disabled
2022.10.07 11:48:08 LOG7[0]: TLS state (connect): SSLv3/TLS read server certificate
2022.10.07 11:48:08 LOG7[0]: TLS state (connect): SSLv3/TLS read server key exchange
2022.10.07 11:48:08 LOG6[0]: Client certificate not requested
2022.10.07 11:48:08 LOG7[0]: TLS state (connect): SSLv3/TLS read server done
2022.10.07 11:48:08 LOG7[0]: TLS state (connect): SSLv3/TLS write client key exchange
2022.10.07 11:48:08 LOG7[0]: TLS state (connect): SSLv3/TLS write change cipher spec
2022.10.07 11:48:08 LOG7[1]: TLS state (connect): SSLv3/TLS write client hello
2022.10.07 11:48:08 LOG7[1]: TLS state (connect): SSLv3/TLS read server hello
2022.10.07 11:48:08 LOG7[0]: TLS state (connect): SSLv3/TLS write finished
2022.10.07 11:48:08 LOG6[1]: Certificate verification disabled
2022.10.07 11:48:08 LOG6[1]: Certificate verification disabled
2022.10.07 11:48:08 LOG7[1]: TLS state (connect): SSLv3/TLS read server certificate
2022.10.07 11:48:08 LOG7[1]: TLS state (connect): SSLv3/TLS read server key exchange
2022.10.07 11:48:08 LOG6[1]: Client certificate not requested
2022.10.07 11:48:08 LOG7[1]: TLS state (connect): SSLv3/TLS read server done
2022.10.07 11:48:08 LOG7[1]: TLS state (connect): SSLv3/TLS write client key exchange
2022.10.07 11:48:08 LOG7[1]: TLS state (connect): SSLv3/TLS write change cipher spec
2022.10.07 11:48:08 LOG7[1]: TLS state (connect): SSLv3/TLS write finished
2022.10.07 11:48:08 LOG7[0]: TLS state (connect): SSLv3/TLS write finished
2022.10.07 11:48:08 LOG7[0]: TLS state (connect): SSLv3/TLS read server session ticket
2022.10.07 11:48:08 LOG7[0]: TLS state (connect): SSLv3/TLS read change cipher spec
2022.10.07 11:48:08 LOG7[0]: TLS state (connect): SSLv3/TLS read finished
2022.10.07 11:48:08 LOG7[0]: New session callback
2022.10.07 11:48:08 LOG7[0]: Peer certificate was cached (2065 bytes)
2022.10.07 11:48:08 LOG6[0]: Session id: 3839BA4C908496A780FD435329E7D830188D40E730D4D9D42AE07A25B6663051
2022.10.07 11:48:08 LOG7[0]:      2 client connect(s) requested
2022.10.07 11:48:08 LOG7[0]:      1 client connect(s) succeeded
2022.10.07 11:48:08 LOG7[0]:      0 client renegotiation(s) requested
2022.10.07 11:48:08 LOG7[0]:      0 session reuse(s)
2022.10.07 11:48:08 LOG6[0]: TLS connected: new session negotiated
2022.10.07 11:48:08 LOG6[0]: TLSv1.2 ciphersuite: ECDHE-RSA-AES256-GCM-SHA384 (256-bit encryption)
2022.10.07 11:48:08 LOG7[0]: Compression: null, expansion: null
2022.10.07 11:48:08 LOG6[0]: Read socket closed (readsocket)
2022.10.07 11:48:08 LOG7[0]: Sending close_notify alert
2022.10.07 11:48:08 LOG7[0]: TLS alert (write): warning: close notify
2022.10.07 11:48:08 LOG6[0]: SSL_shutdown successfully sent close_notify alert
2022.10.07 11:48:08 LOG7[1]: TLS state (connect): SSLv3/TLS write finished
2022.10.07 11:48:08 LOG7[1]: TLS state (connect): SSLv3/TLS read server session ticket
2022.10.07 11:48:08 LOG7[1]: TLS state (connect): SSLv3/TLS read change cipher spec
2022.10.07 11:48:08 LOG7[1]: TLS state (connect): SSLv3/TLS read finished
2022.10.07 11:48:08 LOG7[1]: New session callback
2022.10.07 11:48:08 LOG6[1]: Session id: BD63D31363EEBB8D346298A6B618B271550275CBE3631F731C7FDC2E9554C449
2022.10.07 11:48:08 LOG7[1]:      2 client connect(s) requested
2022.10.07 11:48:08 LOG7[1]:      2 client connect(s) succeeded
2022.10.07 11:48:08 LOG7[1]:      0 client renegotiation(s) requested
2022.10.07 11:48:08 LOG7[1]:      0 session reuse(s)
2022.10.07 11:48:08 LOG6[1]: TLS connected: new session negotiated
2022.10.07 11:48:08 LOG6[1]: TLSv1.2 ciphersuite: ECDHE-RSA-AES256-GCM-SHA384 (256-bit encryption)
2022.10.07 11:48:08 LOG7[1]: Compression: null, expansion: null
2022.10.07 11:48:08 LOG6[0]: socket fd: Broken pipe (32)
2022.10.07 11:48:08 LOG6[0]: writesocket: Socket is closed
2022.10.07 11:48:08 LOG5[0]: Connection closed: 0 byte(s) sent to TLS, 14 byte(s) sent to socket
2022.10.07 11:48:08 LOG7[0]: Deallocating application specific data for session connect address
2022.10.07 11:48:08 LOG7[0]: Remote descriptor (FD=10) closed
2022.10.07 11:48:08 LOG7[0]: Local descriptor (FD=3) closed
2022.10.07 11:48:08 LOG7[0]: Service [rsync] finished (1 left)
2022.10.07 11:48:08 LOG6[1]: Read socket closed (readsocket)
2022.10.07 11:48:08 LOG7[1]: Sending close_notify alert
2022.10.07 11:48:08 LOG7[1]: TLS alert (write): warning: close notify
2022.10.07 11:48:08 LOG6[1]: SSL_shutdown successfully sent close_notify alert
2022.10.07 11:48:08 LOG6[1]: TLS socket closed (SSL_read)
2022.10.07 11:48:08 LOG7[1]: Sent socket write shutdown
2022.10.07 11:48:08 LOG5[1]: Connection closed: 970 byte(s) sent to TLS, 3964 byte(s) sent to socket
2022.10.07 11:48:08 LOG7[1]: Remote descriptor (FD=12) closed
2022.10.07 11:48:08 LOG7[1]: Local descriptor (FD=11) closed
2022.10.07 11:48:08 LOG7[1]: Service [rsync] finished (0 left)
2022/10/07 11:48:08 [54] building file list
sending incremental file list
2022/10/07 11:48:08 [54] rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/cities" failed: Permission denied (13)
2022/10/07 11:48:08 [54] rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/lost+found" failed: Permission denied (13)
2022/10/07 11:48:08 [54] rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/mysql" failed: Permission denied (13)
rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/cities" failed: Permission denied (13)
rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/lost+found" failed: Permission denied (13)
rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/mysql" failed: Permission denied (13)
rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/performance_schema" failed: Permission denied (13)
rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/ratings" failed: Permission denied (13)
2022/10/07 11:48:08 [54] rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/performance_schema" failed: Permission denied (13)
2022/10/07 11:48:08 [54] rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/ratings" failed: Permission denied (13)
2022/10/07 11:48:08 [54] rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/sys" failed: Permission denied (13)
rsync: opendir "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/sys" failed: Permission denied (13)
2022/10/07 11:48:08 [54] server_recv(2) starting pid=168
server_recv(2) starting pid=168
2022/10/07 11:48:08 [54] recv_file_name(.)
recv_file_name(.)
2022/10/07 11:48:08 [54] recv_file_name(ibtmp1)
recv_file_name(ibtmp1)
2022/10/07 11:48:08 [54] recv_file_name(server-cert.pem)
recv_file_name(server-cert.pem)
2022/10/07 11:48:08 [54] recv_file_name(server-key.pem)
recv_file_name(server-key.pem)
2022/10/07 11:48:08 [54] recv_file_name(lost+found)
recv_file_name(lost+found)
2022/10/07 11:48:08 [54] recv_file_name(sys)
recv_file_name(sys)
2022/10/07 11:48:08 [54] recv_file_name(ibdata1)
recv_file_name(ibdata1)
2022/10/07 11:48:08 [54] recv_file_name(ib_logfile1)
recv_file_name(ib_logfile1)
2022/10/07 11:48:08 [54] recv_file_name(client-cert.pem)
recv_file_name(client-cert.pem)
2022/10/07 11:48:08 [54] recv_file_name(ib_logfile0)
recv_file_name(ib_logfile0)
2022/10/07 11:48:08 [54] recv_file_name(public_key.pem)
recv_file_name(public_key.pem)
2022/10/07 11:48:08 [54] recv_file_name(ib_buffer_pool)
recv_file_name(ib_buffer_pool)
2022/10/07 11:48:08 [54] recv_file_name(private_key.pem)
recv_file_name(private_key.pem)
2022/10/07 11:48:08 [54] recv_file_name(ca-key.pem)
recv_file_name(ca-key.pem)
2022/10/07 11:48:08 [54] recv_file_name(cities)
recv_file_name(cities)
2022/10/07 11:48:08 [54] recv_file_name(ratings)
recv_file_name(ratings)
2022/10/07 11:48:08 [54] recv_file_name(ca.pem)
recv_file_name(ca.pem)
2022/10/07 11:48:08 [54] recv_file_name(performance_schema)
recv_file_name(performance_schema)
2022/10/07 11:48:08 [54] recv_file_name(mysql)
recv_file_name(mysql)
2022/10/07 11:48:08 [54] recv_file_name(auto.cnf)
recv_file_name(auto.cnf)
2022/10/07 11:48:08 [54] recv_file_name(client-key.pem)
recv_file_name(client-key.pem)
2022/10/07 11:48:08 [54] received 21 names
received 21 names
2022/10/07 11:48:08 [54] recv_file_list done
recv_file_list done
2022/10/07 11:48:08 [54] get_local_name count=21 .
get_local_name count=21 .
2022/10/07 11:48:08 [54] generator starting pid=168
generator starting pid=168
2022/10/07 11:48:08 [54] delta-transmission enabled
delta-transmission enabled
2022/10/07 11:48:08 [54] recv_files(21) starting
recv_files(21) starting
2022/10/07 11:48:08 [54] [receiver] receiving flist for dir 1
[receiver] receiving flist for dir 1
2022/10/07 11:48:08 [54] received 0 names
received 0 names
2022/10/07 11:48:08 [54] recv_file_list done
recv_file_list done
2022/10/07 11:48:08 [54] [receiver] receiving flist for dir 2
[receiver] receiving flist for dir 2
2022/10/07 11:48:08 [54] received 0 names
received 0 names
2022/10/07 11:48:08 [54] recv_file_list done
recv_file_list done
2022/10/07 11:48:08 [54] [receiver] receiving flist for dir 3
[receiver] receiving flist for dir 3
2022/10/07 11:48:08 [54] received 0 names
received 0 names
2022/10/07 11:48:08 [54] recv_file_list done
recv_file_list done
2022/10/07 11:48:08 [54] [receiver] receiving flist for dir 4
[receiver] receiving flist for dir 4
2022/10/07 11:48:08 [54] received 0 names
received 0 names
2022/10/07 11:48:08 [54] recv_file_list done
recv_file_list done
2022/10/07 11:48:08 [54] [receiver] receiving flist for dir 5
[receiver] receiving flist for dir 5
2022/10/07 11:48:08 [54] received 0 names
received 0 names
2022/10/07 11:48:08 [54] recv_file_list done
recv_file_list done
2022/10/07 11:48:08 [54] [receiver] receiving flist for dir 6
[receiver] receiving flist for dir 6
2022/10/07 11:48:08 [54] received 0 names
received 0 names
2022/10/07 11:48:08 [54] recv_file_list done
recv_file_list done
2022/10/07 11:48:08 [54] [generator] receiving flist for dir 1
[generator] receiving flist for dir 1
2022/10/07 11:48:08 [54] received 0 names
received 0 names
2022/10/07 11:48:08 [54] recv_file_list done
recv_file_list done
2022/10/07 11:48:08 [54] [generator] receiving flist for dir 2
[generator] receiving flist for dir 2
2022/10/07 11:48:08 [54] received 0 names
received 0 names
2022/10/07 11:48:08 [54] recv_file_list done
recv_file_list done
2022/10/07 11:48:08 [54] [generator] receiving flist for dir 3
[generator] receiving flist for dir 3
2022/10/07 11:48:08 [54] received 0 names
received 0 names
2022/10/07 11:48:08 [54] recv_file_list done
recv_file_list done
2022/10/07 11:48:08 [54] [generator] receiving flist for dir 4
[generator] receiving flist for dir 4
2022/10/07 11:48:08 [54] received 0 names
received 0 names
2022/10/07 11:48:08 [54] recv_file_list done
recv_file_list done
2022/10/07 11:48:08 [54] [generator] receiving flist for dir 5
[generator] receiving flist for dir 5
2022/10/07 11:48:08 [54] received 0 names
received 0 names
2022/10/07 11:48:08 [54] recv_file_list done
recv_file_list done
2022/10/07 11:48:08 [54] [generator] receiving flist for dir 6
[generator] receiving flist for dir 6
2022/10/07 11:48:08 [54] received 0 names
received 0 names
2022/10/07 11:48:08 [54] recv_file_list done
recv_file_list done
2022/10/07 11:48:08 [54] recv_generator(.,0)
recv_generator(.,0)
2022/10/07 11:48:08 [54] delete_in_dir(.)
delete_in_dir(.)
2022/10/07 11:48:08 [54] IO error encountered -- skipping file deletion
IO error encountered -- skipping file deletion
2022/10/07 11:48:08 [54] recv_generator(.,1)
recv_generator(.,1)
2022/10/07 11:48:08 [54] recv_generator(auto.cnf,2)
recv_generator(auto.cnf,2)
2022/10/07 11:48:08 [54] recv_generator(ca-key.pem,3)
recv_generator(ca-key.pem,3)
2022/10/07 11:48:08 [54] recv_generator(ca.pem,4)
recv_generator(ca.pem,4)
2022/10/07 11:48:08 [54] ca.pem is uptodate
ca.pem is uptodate
2022/10/07 11:48:08 [54] recv_generator(client-cert.pem,5)
recv_generator(client-cert.pem,5)
2022/10/07 11:48:08 [54] client-cert.pem is uptodate
client-cert.pem is uptodate
2022/10/07 11:48:08 [54] recv_generator(client-key.pem,6)
recv_generator(client-key.pem,6)
2022/10/07 11:48:08 [54] recv_generator(ib_buffer_pool,7)
recv_generator(ib_buffer_pool,7)
2022/10/07 11:48:08 [54] recv_generator(ib_logfile0,8)
recv_generator(ib_logfile0,8)
2022/10/07 11:48:08 [54] recv_generator(ib_logfile1,9)
recv_generator(ib_logfile1,9)
2022/10/07 11:48:08 [54] recv_generator(ibdata1,10)
recv_generator(ibdata1,10)
2022/10/07 11:48:08 [54] recv_generator(ibtmp1,11)
recv_generator(ibtmp1,11)
2022/10/07 11:48:08 [54] recv_generator(private_key.pem,12)
recv_generator(private_key.pem,12)
2022/10/07 11:48:08 [54] recv_generator(public_key.pem,13)
recv_generator(public_key.pem,13)
2022/10/07 11:48:08 [54] public_key.pem is uptodate
public_key.pem is uptodate
2022/10/07 11:48:08 [54] recv_generator(server-cert.pem,14)
recv_generator(server-cert.pem,14)
2022/10/07 11:48:08 [54] server-cert.pem is uptodate
server-cert.pem is uptodate
2022/10/07 11:48:08 [54] recv_generator(server-key.pem,15)
recv_generator(server-key.pem,15)
2022/10/07 11:48:08 [54] recv_generator(cities,16)
recv_generator(cities,16)
2022/10/07 11:48:08 [54] recv_generator(lost+found,17)
recv_generator(lost+found,17)
2022/10/07 11:48:08 [54] recv_generator(mysql,18)
recv_generator(mysql,18)
2022/10/07 11:48:08 [54] recv_generator(performance_schema,19)
recv_generator(performance_schema,19)
2022/10/07 11:48:08 [54] recv_generator(ratings,20)
recv_generator(ratings,20)
2022/10/07 11:48:08 [54] recv_generator(sys,21)
recv_generator(sys,21)
2022/10/07 11:48:08 [54] recv_generator(cities,22)
recv_generator(cities,22)
2022/10/07 11:48:08 [54] delete_in_dir(cities)
delete_in_dir(cities)
2022/10/07 11:48:08 [54] recv_generator(lost+found,23)
recv_generator(lost+found,23)
2022/10/07 11:48:08 [54] delete_in_dir(lost+found)
delete_in_dir(lost+found)
2022/10/07 11:48:08 [54] recv_generator(mysql,24)
recv_generator(mysql,24)
2022/10/07 11:48:08 [54] delete_in_dir(mysql)
delete_in_dir(mysql)
2022/10/07 11:48:08 [54] recv_generator(performance_schema,25)
recv_generator(performance_schema,25)
2022/10/07 11:48:08 [54] delete_in_dir(performance_schema)
delete_in_dir(performance_schema)
2022/10/07 11:48:08 [54] recv_generator(ratings,26)
recv_generator(ratings,26)
2022/10/07 11:48:08 [54] delete_in_dir(ratings)
delete_in_dir(ratings)
2022/10/07 11:48:08 [54] recv_generator(sys,27)
recv_generator(sys,27)
2022/10/07 11:48:08 [54] delete_in_dir(sys)
delete_in_dir(sys)
2022/10/07 11:48:08 [54] generate_files phase=1
generate_files phase=1
2022/10/07 11:48:08 [54] rsync: send_files failed to open "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/auto.cnf": Permission denied (13)
rsync: send_files failed to open "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/auto.cnf": Permission denied (13)
2022/10/07 11:48:08 [54] rsync: send_files failed to open "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/ca-key.pem": Permission denied (13)
rsync: send_files failed to open "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/ca-key.pem": Permission denied (13)
rsync: send_files failed to open "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/client-key.pem": Permission denied (13)
2022/10/07 11:48:08 [54] rsync: send_files failed to open "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/client-key.pem": Permission denied (13)
2022/10/07 11:48:08 [54] rsync: send_files failed to open "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/ib_buffer_pool": Permission denied (13)
rsync: send_files failed to open "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/ib_buffer_pool": Permission denied (13)
rsync: send_files failed to open "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/ib_logfile0": Permission denied (13)
2022/10/07 11:48:08 [54] rsync: send_files failed to open "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/ib_logfile0": Permission denied (13)
2022/10/07 11:48:08 [54] rsync: send_files failed to open "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/ib_logfile1": Permission denied (13)
rsync: send_files failed to open "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/ib_logfile1": Permission denied (13)
2022/10/07 11:48:08 [54] rsync: send_files failed to open "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/ibdata1": Permission denied (13)
2022/10/07 11:48:08 [54] rsync: send_files failed to open "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/ibtmp1": Permission denied (13)
rsync: send_files failed to open "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/ibdata1": Permission denied (13)
rsync: send_files failed to open "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/ibtmp1": Permission denied (13)
2022/10/07 11:48:08 [54] rsync: send_files failed to open "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/private_key.pem": Permission denied (13)
rsync: send_files failed to open "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/private_key.pem": Permission denied (13)
2022/10/07 11:48:08 [54] rsync: send_files failed to open "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/server-key.pem": Permission denied (13)
rsync: send_files failed to open "/mnt/ocp-robot-shop/e805b86de9c7f93eb6b9e74ed952f83d/server-key.pem": Permission denied (13)
        192.96M  99%  179.70GB/s    0:00:00 (xfr#10, to-chk=0/21)2022/10/07 11:48:08 [54] recv_files(.)

recv_files(.)
2022/10/07 11:48:08 [54] recv_files(ca.pem)
recv_files(ca.pem)
2022/10/07 11:48:08 [54] recv_files(client-cert.pem)
recv_files(client-cert.pem)
2022/10/07 11:48:08 [54] recv_files(public_key.pem)
recv_files(public_key.pem)
2022/10/07 11:48:08 [54] recv_files(server-cert.pem)
recv_files(server-cert.pem)
2022/10/07 11:48:08 [54] recv_files(cities)
recv_files(cities)
2022/10/07 11:48:08 [54] recv_files(lost+found)
recv_files(lost+found)
2022/10/07 11:48:08 [54] recv_files(mysql)
recv_files(mysql)
2022/10/07 11:48:08 [54] recv_files(performance_schema)
recv_files(performance_schema)
2022/10/07 11:48:08 [54] recv_files(ratings)
recv_files(ratings)
2022/10/07 11:48:08 [54] recv_files(sys)
recv_files(sys)
2022/10/07 11:48:08 [54] recv_files phase=1
recv_files phase=1
2022/10/07 11:48:08 [54] generate_files phase=2
generate_files phase=2
2022/10/07 11:48:08 [54] recv_files phase=2
recv_files phase=2
2022/10/07 11:48:08 [54] recv_files finished
recv_files finished
2022/10/07 11:48:08 [54] generate_files phase=3
generate_files phase=3
2022/10/07 11:48:08 [54] generate_files finished
generate_files finished

2022/10/07 11:48:08 [54] Number of files: 21 (reg: 14, dir: 7)
Number of files: 21 (reg: 14, dir: 7)
2022/10/07 11:48:08 [54] Number of created files: 10 (reg: 10)
Number of created files: 10 (reg: 10)
2022/10/07 11:48:08 [54] Number of deleted files: 0
Number of deleted files: 0
2022/10/07 11:48:08 [54] Number of regular files transferred: 10
Number of regular files transferred: 10
2022/10/07 11:48:08 [54] Total file size: 192.96M bytes
Total file size: 192.96M bytes
2022/10/07 11:48:08 [54] Total transferred file size: 192.96M bytes
Total transferred file size: 192.96M bytes
2022/10/07 11:48:08 [54] Literal data: 0 bytes
Literal data: 0 bytes
2022/10/07 11:48:08 [54] Matched data: 0 bytes
Matched data: 0 bytes
2022/10/07 11:48:08 [54] File list size: 0
File list size: 0
2022/10/07 11:48:08 [54] File list generation time: 0.001 seconds
File list generation time: 0.001 seconds
2022/10/07 11:48:08 [54] File list transfer time: 0.000 seconds
File list transfer time: 0.000 seconds
2022/10/07 11:48:08 [54] Total bytes sent: 775
Total bytes sent: 775
2022/10/07 11:48:08 [54] Total bytes received: 3.79K
Total bytes received: 3.79K

2022/10/07 11:48:08 [54] sent 775 bytes  received 3.79K bytes  9.12K bytes/sec
sent 775 bytes  received 3.79K bytes  9.12K bytes/sec
2022/10/07 11:48:08 [54] total size is 192.96M  speedup is 42,315.90
total size is 192.96M  speedup is 42,315.90
2022/10/07 11:48:08 [54] rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1189) [sender=3.1.3]
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1189) [sender=3.1.3]

Comment 2 Pranav Gaikwad 2022-10-07 16:16:11 UTC

Root cause: With PSA related changes in MTC, we changed the default SecurityContext for Rsync Pods to comply PSA requirements. It requires Rsync to run as non-root user by default. In OpenShift 4.11 and below, the SecurityContext changes make the Rsync Pods use a wrong SCC (this is unpredictable, it can sometime use the right SCC depending upon SCCs in the cluster). But in OpenShift 4.11 and below, we need Rsync to use `rsync-anyuid` SCC as it makes the storage readable no matter what the filesystem user. 

Fix: Proposed fix https://github.com/migtools/mig-controller/pull/1314

Comment 3 Pranav Gaikwad 2022-10-10 13:20:28 UTC

Cherry-picked into release branch here https://github.com/migtools/mig-controller/pull/1316

Comment 9 Pranav Gaikwad 2022-10-17 18:38:39 UTC

In the previous fix I submitted, the issue with incorrect Security Context was solved. However, whenever there existed a "lost+found" directory in the volume, Rsync would fail because that file is owned by root. Whenever Rsync is running as non-root, we need to skip that directory in transfer which is what the new fix https://github.com/migtools/mig-controller/pull/1318 does.

Comment 17 errata-xmlrpc 2022-10-31 11:10:35 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (Migration Toolkit for Containers (MTC) 1.7.5 bug fix update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2022:7262

Note You need to log in before you can comment on or make changes to this bug.