Fedora Account System
Red Hat Associate
Red Hat Customer
Description of problem: DVMP doesn't accurately record LastObservedProgressPercentages of some of the Rsync Pods even though the percentage is clearly visible in the logs. The problem aggravates when the DVM controller attempts multiple retries for Rsync pods. The progress bar in the UI doesn't show accurate progress percentage. Version-Release number of selected component (if applicable): 1.4.3 How reproducible: Most of the times Steps to Reproduce: The reproducar is not certain. The issue may or may not surface. But following steps worked for me: 1. Deploy data-generator app and network simulation script in the source namespace. 2. Migrate the app and observe progress bar in the UI. 3. Look at DVMP status, you will find that LastObservedProgressPercent field is set to 0 even when logs clearly show a percentage value. Actual results: LastObservedProgressPercent field reflects inaccurate value. Expected results: LastObservedProgressPercent field should show exact value as seen in the pod logs. Additional info:
Verified using MTC 1.5.0 openshift-migration-rhel7-operator@sha256:046840aee4bf73c44ab6fe53f4f5df49a4ca808af8e4496f7e957ef8681415d7 We see the following DVM progress and rsync pod messages: LOG: generate_files phase=1 629.15M 33% 9.72MB/s 0:01:01 (xfr#1, to-chk=3/5)2021/06/17 11:25:26 [28] <f+++++++++ file_1 PROGRESS: NAME CLUSTER POD NAME POD NAMESPACE PROGRESS TRANSFER RATE AGE d8a5bb6b9fd966ac5941babcfd9461f8 host dvm-rsync-qrnvw ocp-41217-dvmprogress 0% 0.00kB/s 1m LOG: generate_files phase=1 629.15M 33% 9.72MB/s 0:01:01 (xfr#1, to-chk=3/5)2021/06/17 11:25:26 [28] <f+++++++++ file_1 1.26G 66% 9.73MB/s 0:02:03 (xfr#2, to-chk=2/5)2021/06/17 11:26:28 [28] <f+++++++++ file_2 PROGRESS: NAME CLUSTER POD NAME POD NAMESPACE PROGRESS TRANSFER RATE AGE d8a5bb6b9fd966ac5941babcfd9461f8 host dvm-rsync-qrnvw ocp-41217-dvmprogress 34% 9.91MB/s 3m The progress reported by the logs and by the DVMP do not match. The DVMP is not reporting the right progress. After some investigation, we found out that the pod is reporting the logs using ^M carriage return character. Hence, the last line reporting file_2 progress is printed like this: 1.26G 66% 9.73MB/s 0:02:03 (xfr#2, to-chk=2/5)2021/06/17 11:26:28 [28] <f+++++++++ file_2 But the actual log line (with carriage return characters) is this one: ^M 636.26M 33% 9.91MB/s 0:02:03 ^M 646.45M 34% 9.61MB/s 0:02:06 ^M 657.36M 34% 9.76MB/s 0:02:03 ^M 668.24M 35% 9.91MB/s 0:02:00 ^M 678.04M 35% 9.54MB/s 0:02:03 ^M 688.32M 36% 9.74MB/s 0:02:00 ^M 698.94M 37% 9.84MB/s 0:01:57 ^M 708.77M 37% 9.59MB/s 0:01:59 ^M 719.95M 38% 9.76MB/s 0:01:56 ^M 731.09M 38% 9.74MB/s 0:01:55 ^M 742.29M 39% 9.65MB/s 0:01:55 ^M 753.40M 39% 9.73MB/s 0:01:53 ^M 763.56M 40% 9.72MB/s 0:01:52 ^M 774.67M 41% 9.93MB/s 0:01:49 ^M 784.76M 41% 9.69MB/s 0:01:51 ^M 796.03M 42% 9.69MB/s 0:01:49 ^M 806.26M 42% 9.71MB/s 0:01:48 ^M 816.94M 43% 9.50MB/s 0:01:50 ^M 827.88M 43% 9.89MB/s 0:01:44 ^M 837.78M 44% 9.73MB/s 0:01:45 ^M 848.07M 44% 9.75MB/s 0:01:44 ^M 858.55M 45% 9.83MB/s 0:01:42 ^M 869.27M 46% 9.55MB/s 0:01:44 ^M 879.79M 46% 9.77MB/s 0:01:40 ^M 890.63M 47% 9.70MB/s 0:01:40 ^M 900.92M 47% 9.63MB/s 0:01:40 ^M 911.61M 48% 9.74MB/s 0:01:37 ^M 921.99M 48% 9.70MB/s 0:01:37 ^M 932.94M 49% 9.74MB/s 0:01:35 ^M 943.49M 49% 9.83MB/s 0:01:33 ^M 953.71M 50% 9.84MB/s 0:01:32 ^M 964.00M 51% 9.73MB/s 0:01:32 ^M 974.32M 51% 9.76MB/s 0:01:31 ^M 984.71M 52% 9.68MB/s 0:01:31 ^M 995.43M 52% 9.69MB/s 0:01:29 ^M 1.01G 53% 9.81MB/s 0:01:27 ^M 1.02G 53% 9.75MB/s 0:01:27 ^M 1.03G 54% 9.74MB/s 0:01:26 ^M 1.04G 54% 9.75MB/s 0:01:25 ^M 1.05G 55% 9.69MB/s 0:01:24 ^M 1.06G 56% 9.75MB/s 0:01:23 ^M 1.07G 56% 9.84MB/s 0:01:21 ^M 1.08G 57% 9.76MB/s 0:01:20 ^M 1.09G 57% 9.77MB/s 0:01:19 ^M 1.10G 58% 9.77MB/s 0:01:18 ^M 1.11G 58% 9.68MB/s 0:01:18 ^M 1.12G 59% 9.77MB/s 0:01:16 ^M 1.13G 59% 9.77MB/s 0:01:15 ^M 1.14G 60% 9.76MB/s 0:01:14 ^M 1.15G 61% 9.88MB/s 0:01:12 ^M 1.16G 61% 9.74MB/s 0:01:12 ^M 1.17G 62% 9.89MB/s 0:01:10 ^M 1.18G 62% 9.72MB/s 0:01:10 ^M 1.19G 63% 9.70MB/s 0:01:09 ^M 1.20G 63% 9.89MB/s 0:01:07 ^M 1.21G 64% 9.61MB/s 0:01:08 ^M 1.23G 64% 9.76MB/s 0:01:06 ^M 1.24G 65% 9.67MB/s 0:01:05 ^M 1.25G 66% 9.56MB/s 0:01:05 ^M 1.26G 66% 9.69MB/s 0:01:03 ^M 1.26G 66% 9.73MB/s 0:02:03 (xfr#2, to-chk=2/5)2021/06/17 11:26:28 [28] <f+++++++++ file_2 When MTC reads the logs lines, it trims the spaces and it only takes into account the first 60 characters of every line in case of the line having more than 60 characters. After removing the spaces and taking only 60 characters, we get this line 636.26M 33% 9.91MB/s 0:02:03 ^M 646.45M 34% And this is progress reported by DVMP, which is not right. The right report should be taken from: ^M 1.26G 66% 9.73MB/s 0:02:03 (xfr#2, to-chk=2/5)2021/06/17 11:26:28 [28] <f+++++++++ file_2 The same happens with the line reporting file_1. It is printed like this: 629.15M 33% 9.72MB/s 0:01:01 (xfr#1, to-chk=3/5)2021/06/17 11:25:26 [28] <f+++++++++ file_1 But the actual log line is this one: ^M 32.77K 0% 0.00kB/s 0:00:00 ^M 10.85M 0% 9.63MB/s 0:03:10 ^M 21.66M 1% 9.70MB/s 0:03:07 ^M 32.80M 1% 9.72MB/s 0:03:06 ^M 43.42M 2% 9.72MB/s 0:03:05 ^M 54.30M 2% 9.91MB/s 0:03:00 ^M 64.68M 3% 9.75MB/s 0:03:02 ^M 75.27M 3% 9.83MB/s 0:03:00 ^M 86.15M 4% 9.75MB/s 0:03:00 ^M 96.31M 5% 9.56MB/s 0:03:02 ^M 107.35M 5% 9.67MB/s 0:02:59 ^M 117.77M 6% 9.60MB/s 0:03:00 ^M 128.68M 6% 9.68MB/s 0:02:57 ^M 139.82M 7% 9.93MB/s 0:02:51 ^M 149.36M 7% 9.64MB/s 0:02:56 ^M 159.71M 8% 9.63MB/s 0:02:55 ^M 170.92M 9% 9.64MB/s 0:02:53 ^M 182.09M 9% 9.44MB/s 0:02:56 ^M 193.23M 10% 9.97MB/s 0:02:46 ^M 203.49M 10% 9.77MB/s 0:02:48 ^M 214.47M 11% 9.93MB/s 0:02:44 ^M 224.99M 11% 9.77MB/s 0:02:46 ^M 235.70M 12% 9.65MB/s 0:02:47 ^M 246.02M 13% 9.74MB/s 0:02:44 ^M 257.20M 13% 9.79MB/s 0:02:42 ^M 267.39M 14% 9.74MB/s 0:02:42 ^M 277.68M 14% 9.64MB/s 0:02:43 ^M 288.65M 15% 9.91MB/s 0:02:37 ^M 298.58M 15% 9.52MB/s 0:02:42 ^M 309.13M 16% 9.74MB/s 0:02:38 ^M 319.36M 16% 9.75MB/s 0:02:37 ^M 330.07M 17% 9.69MB/s 0:02:36 ^M 339.87M 18% 9.76MB/s 0:02:34 ^M 350.39M 18% 9.72MB/s 0:02:34 ^M 361.27M 19% 9.87MB/s 0:02:30 ^M 370.97M 19% 9.62MB/s 0:02:33 ^M 381.94M 20% 9.90MB/s 0:02:28 ^M 391.94M 20% 9.89MB/s 0:02:27 ^M 402.69M 21% 9.62MB/s 0:02:30 ^M 413.56M 21% 9.75MB/s 0:02:27 ^M 423.89M 22% 9.58MB/s 0:02:29 ^M 435.09M 23% 9.86MB/s 0:02:23 ^M 444.99M 23% 9.75MB/s 0:02:24 ^M 456.16M 24% 9.98MB/s 0:02:20 ^M 466.19M 24% 9.74MB/s 0:02:22 ^M 476.77M 25% 9.52MB/s 0:02:24 ^M 486.93M 25% 9.72MB/s 0:02:20 ^M 497.42M 26% 9.51MB/s 0:02:22 ^M 508.17M 26% 9.72MB/s 0:02:18 ^M 518.42M 27% 9.72MB/s 0:02:17 ^M 529.50M 28% 9.72MB/s 0:02:16 ^M 540.44M 28% 9.72MB/s 0:02:15 ^M 550.47M 29% 9.55MB/s 0:02:16 ^M 561.51M 29% 9.55MB/s 0:02:15 ^M 572.69M 30% 9.57MB/s 0:02:14 ^M 583.34M 30% 9.57MB/s 0:02:13 ^M 593.82M 31% 9.83MB/s 0:02:08 ^M 604.54M 32% 9.93MB/s 0:02:06 ^M 614.89M 32% 9.77MB/s 0:02:07 ^M 625.15M 33% 9.77MB/s 0:02:06 ^M 629.15M 33% 9.72MB/s 0:01:01 (xfr#1, to-chk=3/5)2021/06/17 11:25:26 [28] <f+++++++++ file_1 Taking only 60 characters after removing the spaces: 32.77K 0% 0.00kB/s 0:00:00 ^M 10.85M 0% So, instead of the actual progress for file_1, DVMP reports 0% We move the BZ to ASSIGNED status.
It did not work well in MTC 1.5.0 image: registry.stage.redhat.io/rhmtc/openshift-migration-rhel7-operator@sha256:00e77706ca22bcb557d13c16822180fc877e6ea1639a72fda8eb9f5488b039a2 * create a 3.5G (3 files) data in source cluster $ oc get all -n ocp-41883-resizeconfig NAME READY STATUS RESTARTS AGE pod/pvresize-test-55d899f788-8dzqz 1/1 Running 0 34s $ oc -n ocp-41883-resizeconfig exec $(oc get pods -l app=pvresize-test -o jsonpath='{.items[0].metadata.name}' -n ocp-41883-resizeconfig) -- df -mh /data/test Filesystem Size Used Available Use% Mounted on /dev/xvdcl 3.8G 3.5G 271.7M 93% /data/test $ oc -n ocp-41883-resizeconfig exec $(oc get pods -l app=pvresize-test -o jsonpath='{.items[0].metadata.name}' -n ocp-41883-resizeconfig) -- ls -lah /data/test total 4G drwxrwsr-x 3 root 10007200 4.0K Jun 25 12:10 . drwxr-xr-x 3 root root 18 Jun 25 12:10 .. -rw-r--r-- 1 10007200 10007200 1.2G Jun 25 12:10 file_1 -rw-r--r-- 1 10007200 10007200 1.2G Jun 25 12:10 file_2 -rw-r--r-- 1 10007200 10007200 1.2G Jun 25 12:10 file_3 drwxrwS--- 2 root 10007200 16.0K Jun 25 12:09 lost+found * got below rsync log in dvm pod in source cluster $ oc -n ocp-41883-resizeconfig logs dvm-rsync-fztf6 -c rsync-client -f 2021/06/25 12:15:35 [24] building file list sending incremental file list 2021/06/25 12:15:35 [24] server_recv(2) starting pid=8 server_recv(2) starting pid=8 ......... generate_files phase=1 1.26G 33% 53.44MB/s 0:00:22 (xfr#1, to-chk=3/5)2021/06/25 12:15:57 [24] <f+++++++++ file_1 2.52G 66% 53.89MB/s 0:00:44 (xfr#2, to-chk=2/5)2021/06/25 12:16:20 [24] <f+++++++++ file_2 3.77G 100% 54.00MB/s 0:01:06 (xfr#3, to-chk=1/5)2021/06/25 12:16:42 [24] <f+++++++++ file_3 2021/06/25 12:16:42 [24] .d..tp.g... lost+found/ 2021/06/25 12:16:42 [24] recv_files(.) ....... * monitor dvmp in target cluster every 1 second $ while true; do echo "----------";oc get dvmp; sleep 1;done ...... ---------- NAME CLUSTER POD NAME POD NAMESPACE PROGRESS TRANSFER RATE AGE 2c5cbd8a0f0f66755af83322cad32d07 source-cluster ocp-41883-resizeconfig 0% 1s ...... ---------- NAME CLUSTER POD NAME POD NAMESPACE PROGRESS TRANSFER RATE AGE 2c5cbd8a0f0f66755af83322cad32d07 source-cluster dvm-rsync-fztf6 ocp-41883-resizeconfig 1% 0.00kB/s 69s ...... ---------- NAME CLUSTER POD NAME POD NAMESPACE PROGRESS TRANSFER RATE AGE 2c5cbd8a0f0f66755af83322cad32d07 source-cluster dvm-rsync-fztf6 ocp-41883-resizeconfig 35% 54.02MB/s 99s ...... ---------- NAME CLUSTER POD NAME POD NAMESPACE PROGRESS TRANSFER RATE AGE 2c5cbd8a0f0f66755af83322cad32d07 source-cluster dvm-rsync-fztf6 ocp-41883-resizeconfig 100% 54.02MB/s 2m7s The expected result should be 0% -> 33% -> 66% -> 100%
sorry for wrong information, the expected result should not only be 0% -> 33% -> 66% -> 100%. the change path %0->%1->35%->100% make sense.
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) image release advisory 1.5.0), 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/RHEA-2021:2929