Alistair Dsouza
2011-Apr-20 19:44 UTC
files not moved immediately to final destination from temp location after rsync returns with success
Hi, I am using rsync version 3.0.7 on an arm linux based embedded device. The device pulls data periodically from a rsync server and stores the files on an SD card. The partial, temp and final rsync destinations all reside on the SD card. I came across an issue where it seems that the rsync call returned with a success but the files that it pulled are not moved immediately to its final destination. The issue points either to rsync not moving data immediately to its final location of some delay in the virtual file system. However a read system call would flush the block buffer via the VFS. I have a script which periodically calls the rsync client to check if data is available on a server located on a cloud. The script contains two separate rsync calls. The first checks periodically if a file of a particular name is present. The script has logic to know which file name is should be searching for next. Basically the file name has a number in the name and this rysc calls periodically checks for that file. The file pulled by the first rsync call contains info on the data (multiple files contained under a parent directory) that has to be pulled from the server. The second rsync call comes into play when the first rsync call succeeds in pulling the file. When the second rsync call returns with success the name of the file that has to be pulled by the first call is updated and the cycle continues. In case either of the rsync calls fail, the script starts with the first rsync call. <snippet of the script> while : do # get the name of the command file to pull next. CURR_Q_NUM=get_counter REMOTE_Q_FILE="${CURR_Q_NUM}.txt" LOCAL_Q_FILE="${Q_FOLDER}/${CURR_Q_NUM}.txt" # update the source and destination for rsync client SRC=$OPT_RSYNC_USER_NAME@ $OPT_RSYNC_DEV_NAME::$RSYNC_Q_MODULE/$REMOTE_Q_FILE DEST=$LOCAL_Q_FILE rsync --update \ --verbose \ --stats \ --port=$OPT_RSYNC_PORT \ --partial-dir=$PARTIAL_XFER_FOLDER \ --temp-dir=$TEMP_FOLDER \ --bwlimit $CONFIG_PULL_RATE \ --timeout $CONFIG_TIMEOUT \ --contimeout $CONFIG_TIMEOUT \ $SRC $DEST 1>>$RSYNC_LOG 2>&1 if [ $? -eq 0 ]; then process_command_file <<<< if the file was pulled completely then pull the files mentioned in this file. [ $? -eq 0 ] && { update_counter; } <<<< update_counter increments the file name to the next file we should be looking for if all the data was all pulled correctly fi sleep $CONFIG_POLL_PERIOD <<<<< this was configured as 180 seconds. done function process_command_file { # extract the source and destination from the file pulled by te rsync call in the while loop. SRC= .... DEST= ..... rsync --update \ --verbose \ --stats \ --port=$OPT_RSYNC_PORT \ --partial-dir=$PARTIAL_XFER_FOLDER \ --temp-dir=$TEMP_FOLDER \ --recursive \ --bwlimit $CONFIG_PULL_RATE \ --timeout $CONFIG_TIMEOUT \ --contimeout $CONFIG_TIMEOUT \ $SRC $DEST 1>>$RSYNC_LOG 2>&1 local RET=$? if [ "$RET" -eq 0 ] then # if the second rsync call succeeds then process the data FILES=$DEST/* for file in $FILES do # do some processing on the files *<<<<< for some reason in one instance the files were not present immediately in the final location even though rsync pulled the files and returned with success.* done fi return $RET } *<snippet end>* I noticed that the data is pulled by the second rsync call (in process_command_file) but when the script tries to process the data (just one instance was seen) it did not find it in its final location. in this instance when the data was not processed (in the if condition in the process_command_file function) the rsync logs shows the data pulled successfully by both rsync calls but some of the logs of the second rsync call appear after the logs on the next rsync call in the cycle. *<snippet of rsync logs when the issue is seen>* 0000000328.txt * <<<<< corresponding to the rsync call in the while loop the command file is pulled* Number of files: 1 Number of files transferred: 1 Total file size: 108 bytes Total transferred file size: 108 bytes Literal data: 108 bytes Matched data: 0 bytes File list size: 28 File list generation time: 0.001 seconds File list transfer time: 0.000 seconds Total bytes sent: 53 Total bytes received: 213 sent 53 bytes received 213 bytes 76.00 bytes/sec total size is 108 speedup is 0.41 receiving incremental file list *<<<<<<< corresponding to the rsync call in process_command_file function* data/ data/LGC130UB.zip rsync: link_stat "/0000000329.txt" (in q) failed: No such file or directory (2) *<<<<< corresponding to the rsync call in the while loop* * <<<<<< since 0000000329.txt is not yet present on the server the script will loop on the rsync call in the while loop till it finds 000000329.txt* Number of files: 0 Number of files transferred: 0 Total file size: 0 bytes Total transferred file size: 0 bytes Literal data: 0 bytes Matched data: 0 bytes File list size: 3 Total bytes sent: 15 Total bytes received: 8 sent 15 bytes received 8 bytes 9.20 bytes/sec total size is 0 speedup is 0.00 rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1508) [Receiver=3.0.7] meta/ *<<<<<<< corresponding to the rsync call in process_command_file function which should have occurred before the rsync call above it* Number of files: 3 *<<<<< 3 corresponds to data, data/LGC130UB.zip, meta* Number of files transferred: 1 Total file size: 15284642 bytes Total transferred file size: 15284642 bytes Literal data: 15284642 bytes Matched data: 0 bytes File list size: 56 File list generation time: 0.001 seconds File list transfer time: 0.000 seconds Total bytes sent: 68 Total bytes received: 15286657 sent 68 bytes received 15286657 bytes 87103.85 bytes/sec total size is 15284642 speedup is 1.00 rsync: link_stat "/0000000329.txt" (in q) failed: No such file or directory (2) *<<<<< corresponding to the rsync call in the while loop* Number of files: 0 Number of files transferred: 0 Total file size: 0 bytes Total transferred file size: 0 bytes Literal data: 0 bytes Matched data: 0 bytes File list size: 3 Total bytes sent: 15 Total bytes received: 8 sent 15 bytes received 8 bytes 5.11 bytes/sec total size is 0 speedup is 0.00 *<end of snippet>* * * * * *<snippet of rsync logs when everything works fine>* rsync: link_stat "/0000000330.txt" (in q) failed: No such file or directory (2) *<<<<< corresponding to the rsync call in the while loop* Number of files: 0 Number of files transferred: 0 Total file size: 0 bytes Total transferred file size: 0 bytes Literal data: 0 bytes Matched data: 0 bytes File list size: 3 Total bytes sent: 15 Total bytes received: 8 sent 15 bytes received 8 bytes 9.20 bytes/sec total size is 0 speedup is 0.00 rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1508) [Receiver=3.0.7] rsync: link_stat "/0000000330.txt" (in q) failed: No such file or directory (2) *<<<<< corresponding to the rsync call in the while loop* Number of files: 0 Number of files transferred: 0 Total file size: 0 bytes Total transferred file size: 0 bytes Literal data: 0 bytes Matched data: 0 bytes File list size: 3 Total bytes sent: 15 Total bytes received: 8 sent 15 bytes received 8 bytes 6.57 bytes/sec total size is 0 speedup is 0.00 rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1508) [Receiver=3.0.7] 0000000330.txt *<<<<< corresponding to the rsync call in the while loop. we can now process the contents of this file and pull the data.* Number of files: 1 Number of files transferred: 1 Total file size: 108 bytes Total transferred file size: 108 bytes Literal data: 108 bytes Matched data: 0 bytes File list size: 28 File list generation time: 0.001 seconds File list transfer time: 0.000 seconds Total bytes sent: 53 Total bytes received: 213 sent 53 bytes received 213 bytes 59.11 bytes/sec total size is 108 speedup is 0.41 receiving incremental file list *<<<<<<< corresponding to the rsync call in process_command_file function* data/ data/MDL130UB.zip meta/ Number of files: 3 *<<<<< 3 corresponds to data, data/MDL130UB.zip, meta* Number of files transferred: 1 Total file size: 13810445 bytes Total transferred file size: 13810445 bytes Literal data: 13810445 bytes Matched data: 0 bytes File list size: 60 File list generation time: 0.001 seconds File list transfer time: 0.000 seconds Total bytes sent: 68 Total bytes received: 13812284 sent 68 bytes received 13812284 bytes 91776.43 bytes/sec total size is 13810445 speedup is 1.00 rsync: link_stat "/0000000331.txt" (in q) failed: No such file or directory (2) *<<<<< corresponding to the rsync call in the while loop* Number of files: 0 Number of files transferred: 0 Total file size: 0 bytes Total transferred file size: 0 bytes Literal data: 0 bytes Matched data: 0 bytes File list size: 3 Total bytes sent: 15 Total bytes received: 8 sent 15 bytes received 8 bytes 9.20 bytes/sec total size is 0 speedup is 0.00 rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1508) [Receiver=3.0.7] rsync: link_stat "/0000000331.txt" (in q) failed: No such file or directory (2) *<<<<< corresponding to the rsync call in the while loop* Number of files: 0 Number of files transferred: 0 Total file size: 0 bytes Total transferred file size: 0 bytes Literal data: 0 bytes Matched data: 0 bytes File list size: 3 Total bytes sent: 15 Total bytes received: 8 sent 15 bytes received 8 bytes 6.57 bytes/sec total size is 0 speedup is 0.00 rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1508) [Receiver=3.0.7] *<end of snippet>* thanks, Alistair -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://lists.samba.org/pipermail/rsync/attachments/20110421/3567032f/attachment.html>
Alistair Dsouza
2011-Apr-20 19:54 UTC
files not moved immediately to final destination from temp location after rsync returns with success
Also wanted to clarify that both the rsync calls in the script are run to completion (not in the background) and there is a delay of 180 seconds between the two calls. when the issue is seen the logs in the email below show the rsync messages from the two rsync calls are interleaved. regards, Alistair On Thu, Apr 21, 2011 at 1:14 AM, Alistair Dsouza <alistaird at gmail.com>wrote:> Hi, > > I am using rsync version 3.0.7 on an arm linux based embedded device. The > device pulls data periodically from a rsync server and stores the files on > an SD card. > The partial, temp and final rsync destinations all reside on the SD card. > > I came across an issue where it seems that the rsync call returned with a > success but the files that it pulled are not > moved immediately to its final destination. The issue points either to > rsync not moving data immediately to its final location > of some delay in the virtual file system. However a read system call would > flush the block buffer via the VFS. > > I have a script which periodically calls the rsync client to check if data > is available on a server located on a cloud. > The script contains two separate rsync calls. The first checks periodically > if a file of a particular name is present. > The script has logic to know which file name is should be searching for > next. Basically the file name has a number > in the name and this rysc calls periodically checks for that file. > > The file pulled by the first rsync call contains info on the data (multiple > files contained under a parent directory) that has to > be pulled from the server. The second rsync call comes into play when the > first rsync call succeeds in pulling the file. > When the second rsync call returns with success the name of the file that > has to be pulled by the first call is updated and > the cycle continues. In case either of the rsync calls fail, the script > starts with the first rsync call. > > <snippet of the script> > while : > do > # get the name of the command file to pull next. > CURR_Q_NUM=get_counter > REMOTE_Q_FILE="${CURR_Q_NUM}.txt" > LOCAL_Q_FILE="${Q_FOLDER}/${CURR_Q_NUM}.txt" > > # update the source and destination for rsync client > SRC=$OPT_RSYNC_USER_NAME@ > $OPT_RSYNC_DEV_NAME::$RSYNC_Q_MODULE/$REMOTE_Q_FILE > DEST=$LOCAL_Q_FILE > > rsync --update \ > --verbose \ > --stats \ > --port=$OPT_RSYNC_PORT \ > --partial-dir=$PARTIAL_XFER_FOLDER \ > --temp-dir=$TEMP_FOLDER \ > --bwlimit $CONFIG_PULL_RATE \ > --timeout $CONFIG_TIMEOUT \ > --contimeout $CONFIG_TIMEOUT \ > $SRC $DEST 1>>$RSYNC_LOG 2>&1 > > if [ $? -eq 0 ]; then > process_command_file <<<< if the file was pulled completely then > pull the files mentioned in this file. > [ $? -eq 0 ] && { update_counter; } <<<< update_counter > increments the file name to the next file we should be looking for if all > the data was all pulled correctly > fi > > sleep $CONFIG_POLL_PERIOD <<<<< this was configured as 180 seconds. > done > > function process_command_file > { > # extract the source and destination from the file pulled by te > rsync call in the while loop. > SRC= .... > DEST= ..... > > rsync --update \ > --verbose \ > --stats \ > --port=$OPT_RSYNC_PORT \ > --partial-dir=$PARTIAL_XFER_FOLDER \ > --temp-dir=$TEMP_FOLDER \ > --recursive \ > --bwlimit $CONFIG_PULL_RATE \ > --timeout $CONFIG_TIMEOUT \ > --contimeout $CONFIG_TIMEOUT \ > $SRC $DEST 1>>$RSYNC_LOG 2>&1 > > local RET=$? > > if [ "$RET" -eq 0 ] > then > > # if the second rsync call succeeds then process the data > FILES=$DEST/* > > for file in $FILES > do > # do some processing on the files *<<<<< for some reason in > one instance the files were not present immediately in the final location > even though rsync pulled the files and returned with success.* > done > fi > > return $RET > } > *<snippet end>* > > I noticed that the data is pulled by the second rsync call (in > process_command_file) but when the script tries to process the data (just > one instance was seen) it did not find it in its final location. > > in this instance when the data was not processed (in the if condition in > the process_command_file function) the rsync logs shows the data pulled > successfully by both rsync calls but some of the logs of the second rsync > call appear after the logs on the next rsync call in the cycle. > > *<snippet of rsync logs when the issue is seen>* > > 0000000328.txt * <<<<< corresponding to the rsync call > in the while loop the command file is pulled* > > Number of files: 1 > Number of files transferred: 1 > Total file size: 108 bytes > Total transferred file size: 108 bytes > Literal data: 108 bytes > Matched data: 0 bytes > File list size: 28 > File list generation time: 0.001 seconds > File list transfer time: 0.000 seconds > Total bytes sent: 53 > Total bytes received: 213 > > sent 53 bytes received 213 bytes 76.00 bytes/sec > total size is 108 speedup is 0.41 > > > receiving incremental file list *<<<<<<< corresponding to the rsync > call in process_command_file function* > data/ > data/LGC130UB.zip > > rsync: link_stat "/0000000329.txt" (in q) failed: No such file or directory > (2) *<<<<< corresponding to the rsync call in the while loop* > * <<<<<< since 0000000329.txt is not yet present on the server the script > will loop on the rsync call in the while loop till it finds 000000329.txt* > > Number of files: 0 > Number of files transferred: 0 > Total file size: 0 bytes > Total transferred file size: 0 bytes > Literal data: 0 bytes > Matched data: 0 bytes > File list size: 3 > Total bytes sent: 15 > Total bytes received: 8 > > sent 15 bytes received 8 bytes 9.20 bytes/sec > total size is 0 speedup is 0.00 > rsync error: some files/attrs were not transferred (see previous errors) > (code 23) at main.c(1508) [Receiver=3.0.7] > > meta/ *<<<<<<< corresponding to the rsync call in > process_command_file function which should have occurred before the rsync > call above it* > > Number of files: 3 *<<<<< 3 corresponds to data, data/LGC130UB.zip, meta > * > Number of files transferred: 1 > Total file size: 15284642 bytes > Total transferred file size: 15284642 bytes > Literal data: 15284642 bytes > Matched data: 0 bytes > File list size: 56 > File list generation time: 0.001 seconds > File list transfer time: 0.000 seconds > Total bytes sent: 68 > Total bytes received: 15286657 > > sent 68 bytes received 15286657 bytes 87103.85 bytes/sec > total size is 15284642 speedup is 1.00 > > rsync: link_stat "/0000000329.txt" (in q) failed: No such file or directory > (2) *<<<<< corresponding to the rsync call in the while loop* > > Number of files: 0 > Number of files transferred: 0 > Total file size: 0 bytes > Total transferred file size: 0 bytes > Literal data: 0 bytes > Matched data: 0 bytes > File list size: 3 > Total bytes sent: 15 > Total bytes received: 8 > > sent 15 bytes received 8 bytes 5.11 bytes/sec > total size is 0 speedup is 0.00 > *<end of snippet>* > * > * > * > * > *<snippet of rsync logs when everything works fine>* > rsync: link_stat "/0000000330.txt" (in q) failed: No such file or directory > (2) *<<<<< corresponding to the rsync call in the while loop* > > Number of files: 0 > Number of files transferred: 0 > Total file size: 0 bytes > Total transferred file size: 0 bytes > Literal data: 0 bytes > Matched data: 0 bytes > File list size: 3 > Total bytes sent: 15 > Total bytes received: 8 > > sent 15 bytes received 8 bytes 9.20 bytes/sec > total size is 0 speedup is 0.00 > rsync error: some files/attrs were not transferred (see previous errors) > (code 23) at main.c(1508) [Receiver=3.0.7] > > rsync: link_stat "/0000000330.txt" (in q) failed: No such file or directory > (2) *<<<<< corresponding to the rsync call in the while loop* > > Number of files: 0 > Number of files transferred: 0 > Total file size: 0 bytes > Total transferred file size: 0 bytes > Literal data: 0 bytes > Matched data: 0 bytes > File list size: 3 > Total bytes sent: 15 > Total bytes received: 8 > > sent 15 bytes received 8 bytes 6.57 bytes/sec > total size is 0 speedup is 0.00 > rsync error: some files/attrs were not transferred (see previous errors) > (code 23) at main.c(1508) [Receiver=3.0.7] > > 0000000330.txt *<<<<< corresponding to the rsync call in the while loop. > we can now process the contents of this file and pull the data.* > > Number of files: 1 > Number of files transferred: 1 > Total file size: 108 bytes > Total transferred file size: 108 bytes > Literal data: 108 bytes > Matched data: 0 bytes > File list size: 28 > File list generation time: 0.001 seconds > File list transfer time: 0.000 seconds > Total bytes sent: 53 > Total bytes received: 213 > > sent 53 bytes received 213 bytes 59.11 bytes/sec > total size is 108 speedup is 0.41 > > receiving incremental file list *<<<<<<< corresponding to the rsync call > in process_command_file function* > data/ > data/MDL130UB.zip > meta/ > > Number of files: 3 *<<<<< 3 corresponds to data, data/MDL130UB.zip, meta > * > Number of files transferred: 1 > Total file size: 13810445 bytes > Total transferred file size: 13810445 bytes > Literal data: 13810445 bytes > Matched data: 0 bytes > File list size: 60 > File list generation time: 0.001 seconds > File list transfer time: 0.000 seconds > Total bytes sent: 68 > Total bytes received: 13812284 > > sent 68 bytes received 13812284 bytes 91776.43 bytes/sec > total size is 13810445 speedup is 1.00 > > rsync: link_stat "/0000000331.txt" (in q) failed: No such file or directory > (2) *<<<<< corresponding to the rsync call in the while loop* > > Number of files: 0 > Number of files transferred: 0 > Total file size: 0 bytes > Total transferred file size: 0 bytes > Literal data: 0 bytes > Matched data: 0 bytes > File list size: 3 > Total bytes sent: 15 > Total bytes received: 8 > > sent 15 bytes received 8 bytes 9.20 bytes/sec > total size is 0 speedup is 0.00 > rsync error: some files/attrs were not transferred (see previous errors) > (code 23) at main.c(1508) [Receiver=3.0.7] > > rsync: link_stat "/0000000331.txt" (in q) failed: No such file or directory > (2) *<<<<< corresponding to the rsync call in the while loop* > > Number of files: 0 > Number of files transferred: 0 > Total file size: 0 bytes > Total transferred file size: 0 bytes > Literal data: 0 bytes > Matched data: 0 bytes > File list size: 3 > Total bytes sent: 15 > Total bytes received: 8 > > sent 15 bytes received 8 bytes 6.57 bytes/sec > total size is 0 speedup is 0.00 > rsync error: some files/attrs were not transferred (see previous errors) > (code 23) at main.c(1508) [Receiver=3.0.7] > *<end of snippet>* > > thanks, > Alistair >-------------- next part -------------- An HTML attachment was scrubbed... URL: <http://lists.samba.org/pipermail/rsync/attachments/20110421/65b6661a/attachment.html>
Henri Shustak
2011-Apr-20 23:16 UTC
files not moved immediately to final destination from temp location after rsync returns with success
> I am using rsync version 3.0.7 on an arm linux based embedded device. The device pulls data periodically from a rsync server and stores the files on an SD card. The partial, temp and final rsync destinations all reside on the SD card. > > I came across an issue where it seems that the rsync call returned with a success but the files that it pulled are not moved immediately to its final destination.You could try issuing the 'sync' command? However, I do not think believe that this should be required. Perhaps someone else on this list will have some other ideas? ------------------------------------ This email is protected by LBackup http://www.lbackup.org
Wayne Davison
2011-Apr-23 15:36 UTC
files not moved immediately to final destination from temp location after rsync returns with success
On Wed, Apr 20, 2011 at 12:44 PM, Alistair Dsouza <alistaird at gmail.com>wrote:> I came across an issue where it seems that the rsync call returned with a > success but the files that it pulled are not moved immediately to its final > destination. >I think it more likely that you had 2 instances of the script running at the same time. You could use something like "shlock" to prevent that from happening. ..wayne.. -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://lists.samba.org/pipermail/rsync/attachments/20110423/355a44cb/attachment.html>
Alistair Dsouza
2011-Apr-25 12:10 UTC
files not moved immediately to final destination from temp location after rsync returns with success
The two rsync calls had a delay of 180 seconds between them but when the issue was seen the debug prints from the second rsync call were interspersed with the debug logs of the first rsync call. Our system startup scripts start just one instance of the script which has the two rsync calls. Also when the issue was later detected there was one instance of that script running. Have you come across errors with bash scripts where they run the command in the background even when not specified to. If so then that seems to be an explanation as to what took place. We did not see any SD card errors or file system errors in general. Regards, Alistair On Sat, Apr 23, 2011 at 9:06 PM, Wayne Davison <wayned at samba.org> wrote:> On Wed, Apr 20, 2011 at 12:44 PM, Alistair Dsouza <alistaird at gmail.com>wrote: > >> I came across an issue where it seems that the rsync call returned with a >> success but the files that it pulled are not moved immediately to its final >> destination. >> > > I think it more likely that you had 2 instances of the script running at > the same time. You could use something like "shlock" to prevent that from > happening. > > ..wayne.. >-------------- next part -------------- An HTML attachment was scrubbed... URL: <http://lists.samba.org/pipermail/rsync/attachments/20110425/28a32bbb/attachment.html>