8.4. CIFS Pre-population

Strictly speaking CIFS pre-population is not a latency optimization feature but a data store warming feature. The feature overcomes the initial cold data transfer of new files read from a remote CIFS share by going through the remote CIFS share during the night and performing the initial cold transfer. As a result the next morning the data store is warm for the contents of the new files from the remote CIFS share and the users immediately experience the full optimization.

The configuration of the CIFS pre-population requires name of the remote CIFS share, the username and the password to access the remote CIFS share. All files and directories on that remote CIFS share should be readable by that user.

Figure 8.10. CIFS pre-population configuration

CIFS pre-population configuration

The optimization service on the client-side Steelhead appliance needs to see the naked SYN of the CIFS session. The TCP SYN packet will leave the primary interface and should go arrive on the LAN interface where it will be processed as a normal TCP session to be optimized and go through the in-path rules.

When modifying the CIFS pre-population share from the CLI, the share needs to be entered like a Windows path with backslashes. Because the backslash has a different meaning on the CLI, it is required to escape the backslashes. This is the way to escape the name for the share \\192.168.1.1\admin\prepop is \\\\192.168.1.1\\admin\\prepop.

The CIFS pre-population process consists of three steps: The registration of the CIFS share, the initial syncing and the periodical syncing.

8.4.1. The registration of the CIFS share

During the registration the CIFS pre-population process will connect to the remote server, login and map the share.

Figure 8.11. Successful registration of the CIFS pre-population session

CSH rcud[5555]: [rcud/req/.NOTICE] - {- -} Received action: /rbt/rcu/action/share_config
CSH rcud[5555]: [rcud/main/.INFO] - {- -} Adding share:  Share : \\192.168.1.1\admin\prepo \
    p Server name : 192.168.1.1 Server path : \\192.168.1.1\admin\prepop Server port : 0 S \
    hare Mode : 3 Sync freq : 604800
CSH rcud[5555]: [rcud/main/.INFO] - {- -} Share parameters verified locally. Reply to mgmt \
    d
CSH rcud[5555]: [rcud/main/.INFO] - {- -} succ=0, msg=Share registration in progress ...
CSH rcud[5555]: [policy_manager.INFO] - {- -}  @ [126]: Saved policies
CSH rcud[5555]: [rcud/main/.INFO] - {- -} For Share : \\192.168.1.1\admin\prepop
CSH mgmtd[3544]: [mgmtd.NOTICE]: Share registration in progress ... 
CSH webasd[6087]: [web.INFO]: web: Received return code 0, return message 'Share registrat \
    ion in progress ...\n' from gclSession pygs_handle_any_response 
CSH rcud[5555]: [rcud/share/.INFO] - {- -} Share \\192.168.1.1\admin\prepop Enter dispatch \
    _cmd(): cmd=REGISTER_SHARE
CSH rcud[5555]: [rcud/share/.NOTICE] - {- -} dispatch_cmd() START CMD : REGISTER_SHARE Sha \
    re : \\192.168.1.1\admin\prepop
CSH sport[2946]: [splice/client.INFO] 14 {10.0.1.5:47055 192.168.1.1:139} init client 10.0 \
    .1.5:47055 server 192.168.1.1:139 cfe 10.0.1.6:7801 sfe 192.168.1.6:7800 client connec \
    ted: yes 
CSH sport[2946]: [splice/client.INFO] 14 {10.0.1.5:47055 192.168.1.1:139} Start flowing, l \
    port 40281, rport 7800, OPOL_NORMAL, NAGLE_NEVER, PREOPT_NONE, LATOPT_AUTO, TRANSPORT_ \
    ID_NONE, TPTOPT_NONE(0x0), TRPY_NONE 
CSH rcud[5555]: [cifsclient.INFO] - {- -}  @ [320]: Connected to server 192.168.1.1
CSH webasd[6087]: [web.INFO]: web: User admin viewing setupPrepop page. 
CSH sport[2946]: [cifs_neg.INFO] 14 {- -} Dialect[0] = PC NETWORK PROGRAM 1.0 
CSH sport[2946]: [cifs_neg.INFO] 14 {- -} Dialect[1] = MICROSOFT NETWORKS 1.03 
CSH sport[2946]: [cifs_neg.INFO] 14 {- -} Dialect[2] = MICROSOFT NETWORKS 3.0 
CSH sport[2946]: [cifs_neg.INFO] 14 {- -} Dialect[3] = LANMAN1.0 
CSH sport[2946]: [cifs_neg.INFO] 14 {- -} Dialect[4] = LM1.2X002 
CSH sport[2946]: [cifs_neg.INFO] 14 {- -} Dialect[5] = DOS LANMAN2.1 
CSH sport[2946]: [cifs_neg.INFO] 14 {- -} Dialect[6] = NT LANMAN 1.0 
CSH sport[2946]: [cifs_neg.INFO] 14 {- -} Dialect[7] = NT LM 0.12 
CSH sport[2946]: [cifs_neg.INFO] 14 {- -} Dialect[8] = Samba 
CSH sport[2946]: [cifs_neg.INFO] 14 {- -} Dialect[9] = RCU SMB 1 
CSH sport[2946]: [cifs_neg.INFO] 14 {- -} rcu dialect index = 9 
CSH sport[2946]: [cifs_neg.INFO] 14 {- -} Dialect in response before: 6 
CSH sport[2946]: [cifs_neg.INFO] 14 {- -} Dialect in response after: 9 
CSH sport[2946]: [smbmux_cfe/scons.INFO] 14 {10.0.1.5:47055 192.168.1.1:139} Creating pars \
    er type: SMB_PARSER 
CSH sport[2946]: [smbmux_cfe.INFO] 14 {10.0.1.5:47055 192.168.1.1:139} Creating client-sid \
    e SMB parser 
CSH sport[2946]: [smbcfe.INFO] 14 {- -} RTT time: sec:0, usec:305000 
CSH sport[2946]: [smbcfe.INFO] 14 {- -} MAX metadata cache time: 2.000000 sec, data cache  \
    time 20.000000 sec 
CSH sport[2946]: [smbcfe.INFO] 14 {- -} Idle FOI timeouts : 15250 No oplock timeout : 7625 \
     
CSH sport[2946]: [smbcfe.INFO] 14 {10.0.1.5:47055 192.168.1.1:139} Client Native OS Versio \
    n: bytes:  52 69 4f 53                                       RiOS 
CSH sport[2946]: [smbcfe.INFO] 14 {10.0.1.5:47055 192.168.1.1:139} Client Native LAN Manag \
    er: bytes  52 42 54 2d 43 69 66 73   43 6c 69 65 6e 74       RBT-Cifs  Client 
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Registration in progress...
CSH sport[2946]: [smbcfe.INFO] 14 {10.0.1.5:47055 192.168.1.1:139} Client Native OS Versio \
    n: bytes:  52 69 4f 53                                       RiOS 
CSH sport[2946]: [smbcfe.INFO] 14 {10.0.1.5:47055 192.168.1.1:139} Client Native LAN Manag \
    er: bytes  52 42 54 2d 43 69 66 73   43 6c 69 65 6e 74       RBT-Cifs  Client 
CSH sport[2946]: [smbcfe.INFO] 14 {10.0.1.5:47055 192.168.1.1:139} Server Native OS Versio \
    n: unix: Unix 
CSH sport[2946]: [smbcfe.INFO] 14 {10.0.1.5:47055 192.168.1.1:139} Server Native LAN Manag \
    er: Samba: Samba 
CSH sport[2946]: [smbsign_cfe.INFO] 14 {10.0.1.5:47055 192.168.1.1:139} Shutting down sign \
    ing blade for this connection. Reason - Signing feature disabled on SFE. 
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Registration in progress...
CSH sport[2946]: [smbcfe/ccons.INFO] 14 {10.0.1.5:47055 192.168.1.1:139} SMBConsumer::eof( \
    ) this=0x52d2b30, qlen=0 
CSH rcud[5555]: [rcud/share/.NOTICE] - {- -} Completed successfully  CMD : REGISTER_SHARE  \
    Share : \\192.168.1.1\admin\prepop
CSH sport[2946]: [smbcfe/scons.INFO] 14 {10.0.1.5:47055 192.168.1.1:139} SMBConsumer::eof( \
    ) this=0x52d2c08, qlen=0 
CSH sport[2946]: [splice/client.INFO] 14 {10.0.1.5:47055 192.168.1.1:139} fini client 10.0 \
    .1.5:47055 server 192.168.1.1:139 cfe 10.0.1.6:40281 sfe 192.168.1.6:7800 app CIFS 
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Share Registered

It shows up as a normal CIFS session on TCP port 139 or 445 and it should complete with a successful completion: Completed successfully CMD : REGISTER_SHARE Share : \\192.168.1.1\admin\prepop.

8.4.2. Failure of a registration

8.4.2.1. Invalid hostname in the remote share

The host portion of the remote share can be entered by IP addresses or by hostname, for example \\192.168.1.1\admin or \\share.example.com\admin.

If the hostname cannot be resolved, the logs show the error Host not found (authoritative):

Figure 8.12. Registration failed due to an unknown hostname

CSH mgmtd[3544]: [mgmtd.NOTICE]: Share registration in progress ... 
CSH webasd[6087]: [web.INFO]: web: Received return code 0, return message 'Share registrat \
    ion in progress ...\n' from gclSession pygs_handle_any_response 
CSH rcud[5555]: [rcud/share/.INFO] - {- -} Share \\foo.example.com\test Enter dispatch_cmd \
    (): cmd=REGISTER_SHARE
CSH rcud[5555]: [rcud/share/.NOTICE] - {- -} dispatch_cmd() START CMD : REGISTER_SHARE Sha \
    re : \\foo.example.com\test
CSH webasd[6087]: [web.INFO]: web: User admin viewing setupPrepop page. 
CSH rcud[5555]: [cifsclient.NOTICE] - {- -}  @ [233]: Host not found (authoritative)
CSH rcud[5555]: [rcud/client/.NOTICE] - {- -} kerberos authentication on port 139 Failed,  \
    trying NTLMSSP...
CSH rcud[5555]: [cifsclient.NOTICE] - {- -}  @ [233]: Host not found (authoritative)
CSH rcud[5555]: [rcud/client/.NOTICE] - {- -} Logon to port: 139 Failed: 
CSH rcud[5555]: [rcud/client/.NOTICE] - {- -} Retrying alternate CIFS port...
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Registration in progress...
CSH rcud[5555]: [cifsclient.NOTICE] - {- -}  @ [233]: Host not found (authoritative)
CSH rcud[5555]: [rcud/client/.NOTICE] - {- -} kerberos authentication on port 445 Failed,  \
    trying NTLMSSP...
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Registration in progress...
CSH rcud[5555]: [cifsclient.NOTICE] - {- -}  @ [233]: Host not found (authoritative)
CSH rcud[5555]: [rcud/client/.NOTICE] - {- -} Network error. Success, error no : 0 => erro \
    r_info.h:235
CSH rcud[5555]: [rcud/client/.WARN] - {- -} run_rbcp_cmd_v3 : Connecting to server failed. \
      Server : foo.example.com Share : \\foo.example.com\test
CSH rcud[5555]: [rcud/share/.NOTICE] - {- -} record_start_to_status_file(): Received unkno \
    wn command: 0
CSH rcud[5555]: [rcud/share/.NOTICE] - {- -}  got unknown cmd:0
CSH rcud[5555]: [rcud/share/.NOTICE] - {- -} Completed with Error   CMD : REGISTER_SHARE S \
    hare : \\foo.example.com\test
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Share has error

8.4.2.2. Remote host doesn't respond

If the host doesn't exist or doesn't respond, the logs show the error: Network error. Connection reset by peer, error no : 104:

Figure 8.13. Registration failed due to an non-responding remote server

CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Registration in progress...
CSH last message repeated 2 times
CSH sport[2946]: [segstore/peertable.INFO] - {- -} Attempting to write stat table to offse \
    t 1. Num pages: 9 
CSH sport[2946]: [segstore/peertable.INFO] - {- -} Write stat table complete, error 0 
CSH kernel: [intercept.WARN] Detected SYN retransmits for a PFSv3 connection.  Potential r \
    easons include the remote host or network being down, probe filtering, and asymmetric  \
    routing.
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Registration in progress...
CSH kernel: [intercept.WARN] Detected SYN retransmits for a PFSv3 connection.  Potential r \
    easons include the remote host or network being down, probe filtering, and asymmetric  \
    routing.
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Registration in progress...
CSH last message repeated 3 times
CSH rcud[5555]: [cifsclient.INFO] - {- -}  @ [320]: Connected to server 192.168.1.2
CSH rcud[5555]: [cifsclient.NOTICE] - {- -}  @ [53]: Send failed
CSH rcud[5555]: [rcud/client/.NOTICE] - {- -} Logon to port: 139 Failed: 
CSH rcud[5555]: [rcud/client/.NOTICE] - {- -} Retrying alternate CIFS port...
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Registration in progress...
CSH kernel: [intercept.WARN] Detected SYN retransmits for a PFSv3 connection.  Potential r \
    easons include the remote host or network being down, probe filtering, and asymmetric  \
    routing.
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Registration in progress...
CSH kernel: [intercept.WARN] Detected SYN retransmits for a PFSv3 connection.  Potential r \
    easons include the remote host or network being down, probe filtering, and asymmetric  \
    routing.
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Registration in progress...
CSH last message repeated 4 times
CSH rcud[5555]: [cifsclient.INFO] - {- -}  @ [320]: Connected to server 192.168.1.2
CSH rcud[5555]: [cifsclient.NOTICE] - {- -}  @ [53]: Send failed
CSH rcud[5555]: [rcud/client/.NOTICE] - {- -} Network error. Connection reset by peer, err \
    or no : 104
CSH rcud[5555]: [rcud/client/.WARN] - {- -} run_rbcp_cmd_v3 : Connecting to server failed. \
      Server : 192.168.1.2 Share : \\192.168.1.2\admin\prepop
CSH rcud[5555]: [rcud/share/.NOTICE] - {- -} record_start_to_status_file(): Received unkno \
    wn command: 0
CSH rcud[5555]: [rcud/share/.NOTICE] - {- -}  got unknown cmd:0
CSH rcud[5555]: [rcud/share/.NOTICE] - {- -} Completed with Error   CMD : REGISTER_SHARE S \
    hare : \\192.168.1.2\admin\prepop
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Share has error

8.4.2.3. Authentication failed

If the username or password provided is incorrect, the logs will show Session setup failed. Status code : NT_STATUS_LOGON_FAILURE:

Figure 8.14. Registration failed due to a login failure

CSH rcud[5555]: [rcud/client/.NOTICE] - {- -} Session setup failed. Status code : NT_STATU \
    S_LOGON_FAILURE => ntlm_session_impl.cc:131
CSH rcud[5555]: [rcud/client/.WARN] - {- -} run_rbcp_cmd_v3 : Connecting to server failed. \
      Server : 192.168.1.1 Share : \\192.168.1.1\prepop
CSH rcud[5555]: [rcud/share/.NOTICE] - {- -} Completed with Error   CMD : REGISTER_SHARE S \
    hare : \\192.168.1.1\prepop
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Share has error

8.4.2.4. Invalid path on remote server

If the path on the remote server does not exist, the logs will show Failed to map share, because network path is unavailable:

Figure 8.15. Registration failed due to a login failure

CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Registration in progress...
CSH rcud[5555]: [rcud/client/.NOTICE] - {- -} Could not connect to share \\192.168.1.1\pre \
    pop. Tree connect failed. Status code : Failed to map share, because network path is u \
    navailable => tree_connect_impl.cc:90
CSH rcud[5555]: [rcud/client/.WARN] - {- -} run_rbcp_cmd_v3 : Connecting to server failed. \
      Server : 192.168.1.1 Share : \\192.168.1.1\prepop
CSH rcud[5555]: [rcud/share/.NOTICE] - {- -} record_start_to_status_file(): Received unkno \
    wn command: 0
CSH rcud[5555]: [rcud/share/.NOTICE] - {- -}  got unknown cmd:0
CSH rcud[5555]: [rcud/share/.NOTICE] - {- -} Completed with Error   CMD : REGISTER_SHARE S \
    hare : \\192.168.1.1\prepop
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Share has error

8.4.3. The syncing of data

When the registration has completed successfully, the syncing needs to be enabled. From the CLI this can be done with the command prepop share modify remote-path <share> syncing true.

In this example, the remote share has two files in it: \foo.doc and \bar\bar.pdf.

Figure 8.16. A successful sync

CSH rcud[5555]: [crawler.INFO] - {- -} Get initial copy started at Fri 2014-Jan-03 21:29:0 \
    1
CSH rcud[5555]: [cifsfs.INFO] - {- -}  @ [199]: Base cifs sync directory = '\prepop'
CSH sport[2946]: [smbcfe/file.INFO] 17 {10.0.1.5:47717 192.168.1.1:139} process_trans2_fin \
    dfirst_response() has search attr : 23 
CSH sport[2946]: [smbcfe/file.INFO] 17 {10.0.1.5:47717 192.168.1.1:139} process_trans2_fin \
    dfirst_response() has search attr : 23 
CSH rcud[5555]: [sync_file.INFO] - {- -}  @ [207]: Syncing file \foo.doc
CSH last message repeated 4 times
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Get initial copy in progress s \
    ince Fri Jan  3 21:28:59 2014
CSH rcud[5555]: [sync_file.INFO] - {- -}  @ [207]: Syncing file \foo.doc
CSH rcud[5555]: [sync_file.INFO] - {- -}  @ [207]: Syncing file \bar\bar.pdf
CSH last message repeated 4 times
CSH rcud[5555]: [rcud/req/.NOTICE] - {- -} Received action: /rbt/rcu/action/share_config
CSH rcud[5555]: [rcud/share/.NOTICE] - {- -}  Syncing changed for Share : \\192.168.1.1\ad \
    min\prepop Old syncing : 1 New syncing: 0
CSH rcud[5555]: [rcud/main/.INFO] - {- -} succ=0, msg=Share modify succeeded
CSH mgmtd[3544]: [mgmtd.NOTICE]: Share modify succeeded 
CSH rcud[5555]: [sync_file.INFO] - {- -}  @ [207]: Syncing file \bar\bar.pdf
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Get initial copy in progress s \
    ince Fri Jan  3 21:28:59 2014
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Get initial copy in progress s \
    ince Fri Jan  3 21:28:59 2014
CSH rcud[5555]: [sync_file.INFO] - {- -}  @ [207]: Syncing file \bar\bar.pdf
CSH rcud[5555]: [crawler/sync_lists.INFO] - {- -}  @ [194]: Synced file : \foo.doc
CSH rcud[5555]: [crawler/sync_lists.INFO] - {- -}  @ [194]: Synced file : \bar\bar.pdf
CSH sport[2946]: [smbcfe/file.NOTICE] 17 {10.0.1.5:47717 192.168.1.1:139}  File::add_trans \
    2_findnext_data() last entries dont match : \ 
CSH rcud[5555]: [crawler.INFO] - {- -} Get initial copy completed successfully at Fri 2014 \
    -Jan-03 21:29:14
CSH rcud[5555]: [crawler.INFO] - {- -} Received 2 files, 0 objects have error. (34125972 b \
    ytes were received in 13.7194 seconds at 19.8993 Mbps)
CSH sport[2946]: [smbcfe/ccons.INFO] 17 {10.0.1.5:47717 192.168.1.1:139} SMBConsumer::eof( \
    ) this=0x52f0130, qlen=0 
CSH rcud[5555]: [rcud/share/.NOTICE] - {- -} Completed successfully  CMD : GET_INITIAL_COP \
    Y Share : \\192.168.1.1\admin\prepop
CSH sport[2946]: [smbcfe/scons.INFO] 17 {10.0.1.5:47717 192.168.1.1:139} SMBConsumer::eof( \
    ) this=0x52f0208, qlen=0 
CSH sport[2946]: [splice/client.INFO] 17 {10.0.1.5:47717 192.168.1.1:139} fini client 10.0 \
    .1.5:47717 server 192.168.1.1:139 cfe 10.0.1.6:40284 sfe 192.168.1.6:7800 app CIFS 
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Share idle

The Initial Copy log file shows it as:

Figure 8.17. Log file of the Initial Copy

Get initial copy started at Fri 2014-Jan-03 21:29:01
Synced file : \foo.doc
Synced file : \bar\bar.pdf
Get initial copy completed successfully at Fri 2014-Jan-03 21:29:14
Received 2 files, 0 objects have error. (34125972 bytes were received in 13.7194 seconds a \
    t 19.8993 Mbps)

8.4.4. Failure of syncing of data

8.4.4.1. Client-side Steelhead doesn't see the CIFS session

In previous RiOS versions, if the client-side Steelhead appliance did not see the CIFS pre-population session, the CIFS pre-population process would warn about this and abort.

With the new implementation this doesn't happen anymore. The best way to check is to initiate a manual sync and confirm that the TCP session is optimized. This can be done with the command prepop share manual-sync remote-path <path>

Figure 8.18. Manually starting a CIFS pre-population sync

CSH (config) # prepop share manual-sync remote-path \\\\192.168.1.1\\admin\\prepop 
Share manual sync in progress...

This can be caused by:

  • The cable of the primary interface is attached to the WAN router instead of to the LAN switch. If this is on design, consider connecting the auxiliary interface to the LAN switch and a routing statement to force traffic to the CIFS servers to go via the gateway on the auxiliary interface.

  • In case of a parallel cluster, the traffic from the LAN switch does not go via this Steelhead appliance. The way around this could be to configure the data store synchronization and to enable the CIFS pre-population on the Steelhead appliance through which the naked SYN normally goes.

  • In-path rules on the Steelhead appliance prevent optimization from this traffic. The way around this would be to allow optimization from the Steelhead appliance primary interface to the CIFS servers.

8.4.4.2. Unable to read the files

When the CIFS pre-population process cannot read a certain file or directory, it will mark it as failed.

In this example, the file bar\bar.pdf is not readable by the specified user.

Figure 8.19. Unable to read some of the files

CSH rcud[5555]: [crawler.INFO] - {- -} Get initial copy started at Fri 2014-Jan-03 21:23:5 \
    7
CSH rcud[5555]: [cifsfs.INFO] - {- -}  @ [199]: Base cifs sync directory = '\prepop'
CSH sport[2946]: [smbcfe/file.INFO] 16 {10.0.1.5:47574 192.168.1.1:139} process_trans2_fin \
    dfirst_response() has search attr : 23 
CSH sport[2946]: [smbcfe/file.INFO] 16 {10.0.1.5:47574 192.168.1.1:139} process_trans2_fin \
    dfirst_response() has search attr : 23 
CSH rcud[5555]: [sync_obj.ERR] - {- -}  @ [59]: Nt Create AndX failed. Status code : NT_ST \
    ATUS_ACCESS_DENIED => nt_create_andx_impl.cc:94. For \bar\bar.pdf
CSH rcud[5555]: [sync_file.INFO] - {- -}  @ [207]: Syncing file \foo.doc
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Get initial copy in progress s \
    ince Fri Jan  3 21:23:55 2014
CSH rcud[5555]: [sync_file.INFO] - {- -}  @ [207]: Syncing file \foo.doc
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Get initial copy in progress s \
    ince Fri Jan  3 21:23:55 2014
CSH rcud[5555]: [sync_file.INFO] - {- -}  @ [207]: Syncing file \foo.doc
CSH rcud[5555]: [sync_file.INFO] - {- -}  @ [207]: Syncing file \foo.doc
CSH rcud[5555]: [sync_file.INFO] - {- -}  @ [207]: Syncing file \bar\bar.pdf
CSH rcud[5555]: [crawler/sync_lists.INFO] - {- -}  @ [194]: Synced file : \foo.doc
CSH rcud[5555]: [crawler/sync_lists.INFO] - {- -}  @ [194]: Synced file : \bar\bar.pdf
CSH rcud[5555]: [rcud/client/.ERR] - {- -} Sync error. 
CSH rcud[5555]: [rcud/client/.ERR] - {- -} Failed to sync share \\192.168.1.1\admin. 
CSH rcud[5555]: [crawler.INFO] - {- -} Get initial copy completed with error.
CSH rcud[5555]: [crawler.INFO] - {- -} Received 1 files, 1 objects have error. (17062986 b \
    ytes were received in 11.5794 seconds at 11.7885 Mbps)
CSH sport[2946]: [smbcfe.INFO] 16 {10.0.1.5:47574 192.168.1.1:139} clearing pending req:   \
    uid: 0x64 tid: 0x1 pid: 0x15b3 mid: 0x11f omid: 0x11f smid: 0x11f cmd: close subcmd: 0 \
     infolvl: 0 fid: 0x1cb5 status: 1 len 45 time: 1388744649.518695 sec 
CSH sport[2946]: [smbcfe/ccons.INFO] 16 {10.0.1.5:47574 192.168.1.1:139} SMBConsumer::eof( \
    ) this=0x52f1530, qlen=0 
CSH rcud[5555]: [rcud/share/.NOTICE] - {- -} Completed with Error   CMD : GET_INITIAL_COPY \
     Share : \\192.168.1.1\admin\prepop

The Initial Copy log shows:

Figure 8.20. Initial copy failed due to reading errors

Get initial copy started at Fri 2014-Jan-03 21:23:57
Synced file : \foo.doc
Error in syncing file \bar\bar.pdf
Get initial copy completed with error.
Received 1 files, 1 objects have error. (17062986 bytes were received in 11.5794 seconds a \
    t 11.7885 Mbps)

To prevent the failure of one or two files which couldn't be synchronized to be seen as a full failure of the Initial Sync, a failure ignore percentage can be configured:

Figure 8.21. CIFS pre-population failure settings

CSH (config) # show prepop settings 
Maximum Mpx Count Percentage:    40
Ignore Percentage:    0
CSH (config) # prepop settings ignore-pct 10
Processed RCU configuration command.
CSH (config) # show prepop settings 
Maximum Mpx Count Percentage:    40
Ignore Percentage:    10

Now up to 10% of the files to be synced can fail and the initial sync is still considered to be successful.

8.4.5. Periodical syncing

After the initial syncing, the periodical syncing checks for new files and updated files.

Figure 8.22. No new files found during the periodical sync

CSH rcud[5555]: [crawler.INFO] - {- -} Sync started at Fri 2014-Jan-03 21:33:15
CSH rcud[5555]: [cifsfs.INFO] - {- -}  @ [199]: Base cifs sync directory = '\prepop'
CSH sport[2946]: [smbcfe/file.INFO] 19 {10.0.1.5:47840 192.168.1.1:139} process_trans2_fin \
    dfirst_response() has search attr : 23 
CSH sport[2946]: [smbcfe/file.INFO] 19 {10.0.1.5:47840 192.168.1.1:139} process_trans2_fin \
    dfirst_response() has search attr : 23 
CSH sport[2946]: [smbcfe/file.NOTICE] 19 {10.0.1.5:47840 192.168.1.1:139}  File::add_trans \
    2_findnext_data() last entries dont match : \ 
CSH rcud[5555]: [crawler.INFO] - {- -} Sync completed successfully at Fri 2014-Jan-03 21:3 \
    3:16
CSH rcud[5555]: [crawler.INFO] - {- -} Received 0 files, 0 objects have error. (0 bytes we \
    re received in 1.26024 seconds at 0 Mbps)
CSH sport[2946]: [smbcfe/ccons.INFO] 19 {10.0.1.5:47840 192.168.1.1:139} SMBConsumer::eof( \
    ) this=0x5494530, qlen=0 
CSH rcud[5555]: [rcud/share/.NOTICE] - {- -} Completed successfully  CMD : START_SYNC Shar \
    e : \\192.168.1.1\admin\prepop
CSH sport[2946]: [smbcfe/scons.INFO] 19 {10.0.1.5:47840 192.168.1.1:139} SMBConsumer::eof( \
    ) this=0x5494608, qlen=0 
CSH sport[2946]: [splice/client.INFO] 19 {10.0.1.5:47840 192.168.1.1:139} fini client 10.0 \
    .1.5:47840 server 192.168.1.1:139 cfe 10.0.1.6:40286 sfe 192.168.1.6:7800 app CIFS 
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : Share idle

The Last Sync log files show as:

Figure 8.23. The Last Sync log files shows no new files found

Sync started at Fri 2014-Jan-03 21:33:15
Sync completed successfully at Fri 2014-Jan-03 21:33:16
Received 0 files, 0 objects have error. (0 bytes were received in 1.26024 seconds at 0 Mbp \
    s)

If the timestamp of a remote file has changed or a new file has been detected, it will be transferred:

Figure 8.24. New files found during the periodical sync

CSH rcud[5555]: [crawler.INFO] - {- -} Sync started at Fri 2014-Jan-03 21:34:15
CSH rcud[5555]: [cifsfs.INFO] - {- -}  @ [199]: Base cifs sync directory = '\prepop'
CSH sport[2946]: [smbcfe/file.INFO] 20 {10.0.1.5:47863 192.168.1.1:139} process_trans2_fin \
    dfirst_response() has search attr : 23 
CSH last message repeated 2 times
CSH rcud[5555]: [sync_file.INFO] - {- -}  @ [207]: Syncing file \quux\quux.mbox
CSH rcud[5555]: [sync_file.INFO] - {- -}  @ [207]: Syncing file \quux\quux.mbox
CSH rcud[5555]: [rcud/share/.INFO] - {- -}  Status string : START_SYNC in progress since F \
    ri Jan  3 21:34:12 2014
CSH rcud[5555]: [sync_file.INFO] - {- -}  @ [207]: Syncing file \quux\quux.mbox
CSH last message repeated 3 times
CSH rcud[5555]: [crawler/sync_lists.INFO] - {- -}  @ [194]: Synced file : \quux\quux.mbox
CSH sport[2946]: [smbcfe/file.NOTICE] 20 {10.0.1.5:47863 192.168.1.1:139}  File::add_trans \
    2_findnext_data() last entries dont match : \ 
CSH rcud[5555]: [crawler.INFO] - {- -} Sync completed successfully at Fri 2014-Jan-03 21:3 \
    4:23
CSH rcud[5555]: [crawler.INFO] - {- -} Received 1 files, 0 objects have error. (17062986 b \
    ytes were received in 7.97558 seconds at 17.1152 Mbps)

The Last Sync log files show as:

Figure 8.25. The Last Sync log files shows new or updated files found

Sync started at Fri 2014-Jan-03 21:34:15
Synced file : \quux\quux.mbox
Sync completed successfully at Fri 2014-Jan-03 21:34:23
Received 1 files, 0 objects have error. (17062986 bytes were received in 7.97558 seconds a \
    t 17.1152 Mbps)

The status of the CIFS pre-population process can be determined with the command show prepop stats shares:

Figure 8.26. Status of the pre-population shares during syncing and when the share is idle

CSH # show prepop stats shares
+=============================
| Prepopulation name: '\\192.168.1.1\admin\prepop'
|
| ----- Statistics -----
|   Receiving                : NONE
|   Files Received           : 1
|   Directories Received     : 0
|   Bytes Received           : 17062986
CSH # show prepop stats shares
+=============================
| Prepopulation name: '\\192.168.1.1\admin\prepop'
|
| ----- Statistics -----
|   No action in progress