Table of contents

Logs

The SyncPlanet service status and actions are stored on disk as readable text log files to allow users to keep track of their activity and for troubleshooting purposes.

Overview

SyncPlanet uses several types of logs:

error.log A single file chronologically storing the network status (connections and disconnections) and file systems status for each connected storage (listing the type of any encountered error)
Rsync transfer logs The Rsync activity produced by rsync --log-file stores every file transfer made as text files. They are sorted by date, storage name, and direction to ease reading and analysis. They are useful to view and debug the activity of a channel, its bandwidth, and to track a file and deliveries.

Note

Approximately 2GB of logs will be created in total (amounting to only a few dozen MB once compressed) for a 2 years long project with 4 synchronised storages.

Log Files Location

Depending on the configuration of a project, the log files will be located in the system's folders under /var/log/syncplanet or in the synchronised project folders under the {PROJECT_ROOT}/.syncp/log folder. Log files are generated on the machine where the SyncPlanet agents are running.

Rsync Transfer Logs

Naming Convention

The transfer log files are named and sorted by date, the storage's name and its direction: <date>_<storage>_<direction>.log

The date is created according to the following logic:

200514_lestudio_up.log
│ │ │  │        └── direction
│ │ │  └── storage's name
│ │ └── day 2 digits       
│ └── month 2 digits
└───── year 2 digits

The naming convention using shell format is: $(date +%y%m%d)_${storage}_${direction}.log

To understand the format used by the logs, please look at the rsync manual page regarding logs or this thread

Log Breakdown

Each log starts with the following 2 lines:

2023/02/06 00:01:26 [778698] building file list
2023/02/06 00:09:06 [778698] sent 13899793 bytes  received 22841 bytes  total size 379758698250

In this example, the first iteration on that date happened at 00:01 26 seconds. Rsync starts by building up lists of files existing at the source and destination. 7 minutes later, the analysis is done and the log is immediately being written down as comparing the existing lists with the options in used has not triggered any action. Further iterations will happen roughly every 8 minutes and will take approximately the same time to complete, always without transfering any file:

2023/02/06 00:20:40 [781381] building file list
2023/02/06 00:28:18 [781381] sent 13900321 bytes  received 23369 bytes  total size 379758698250
2023/02/06 00:39:37 [784064] building file list
2023/02/06 00:48:54 [784064] sent 13900165 bytes  received 23213 bytes  total size 379758698250
2023/02/06 00:58:58 [786747] building file list
2023/02/06 01:06:37 [786747] sent 13899773 bytes  received 22821 bytes  total size 379758698250
2023/02/06 01:17:49 [789430] building file list
2023/02/06 01:25:55 [789430] sent 13899733 bytes  received 22781 bytes  total size 379758698250
2023/02/06 01:36:44 [792113] building file list
2023/02/06 01:45:33 [792113] sent 13899441 bytes  received 22489 bytes  total size 379758698250
[...]

The first actions on the receiver were triggered by an iteration that started at 05:08 GMT. The following actions were taken:

The creation of a folder pub/3d/asset/chr/fourmi-General/shd/unreal/export/w008/
The copy of a new file chr_fourmi-General_material_instances.json dans ce dossier
The copy of a new file prp_chaiseBebe-A_rig_lo_r008.mb in an existing folder pub/3d/asset/prp/chaiseBebe-A/rig/maya/

2023/02/06 05:08:46 [821716] building file list 
2023/02/06 05:09:08 [821716] cd+++++++++ pub/3d/asset/chr/fourmi-General/shd/unreal/export/w008/ 
2023/02/06 05:09:08 [821716] <f+++++++++ pub/3d/asset/chr/fourmi-General/shd/unreal/export/w008/chr_fourmi-General_material_instances.json 
2023/02/06 05:09:19 [821716] <f+++++++++ pub/3d/asset/prp/chaiseBebe-A/rig/maya/prp_chaiseBebe-A_rig_lo_r008.mb 
2023/02/06 05:16:44 [821716] sent 14049019 bytes  received 22807 bytes  total size 379759369159

At 08:01, we notice similar actions, then we find a file for which <f..t...... is specified: it was updated on the receiver because its mtime date (t, its timestamp) was modified. Then, an other file <f.st...... was updated because its size (s, size) and its date were modified:

2023/02/06 08:01:47 [846943] building file list
2023/02/06 08:01:52 [846943] cd+++++++++ pub/3d/asset/bnk/brinHerbe-A/shd/
2023/02/06 08:01:52 [846943] <f+++++++++ pub/3d/asset/bnk/brinHerbe-A/shd/bnk_brinHerbe-A_shd_r001.png
2023/02/06 08:02:02 [846943] cd+++++++++ pub/3d/asset/bnk/sapin-A/shd/
2023/02/06 08:02:02 [846943] <f+++++++++ pub/3d/asset/bnk/sapin-A/shd/bnk_sapin-A_shd_r001.png
2023/02/06 08:02:10 [846943] cd+++++++++ pub/3d/asset/chr/fourmi-General/shd/unreal/export/w013/
2023/02/06 08:02:10 [846943] <f+++++++++ pub/3d/asset/chr/fourmi-General/shd/unreal/export/w013/chr_fourmi-General_material_instances.json
2023/02/06 08:02:12 [846943] <f..t...... pub/3d/asset/chr/meme-var/shd/unreal/export/w004/chr_meme-var_material_instances.json
2023/02/06 08:02:35 [846943] <f.st...... pub/3d/asset/set/DesertRencontreNuageExt/rig/maya/set_DesertRencontreNuageExt_rig_r001.ma
2023/02/06 08:07:19 [846943] cd+++++++++ pub/3d/sequence/sq0590/lay/
2023/02/06 08:07:19 [846943] cd+++++++++ pub/3d/sequence/sq0590/lay/maya/
2023/02/06 08:07:20 [846943] <f+++++++++ pub/3d/sequence/sq0590/lay/maya/sq0590_lay_r002.ma
2023/02/06 08:07:20 [846943] <f+++++++++ pub/3d/sequence/sq0590/lay/maya/sq0590_lay_sh0110_r002.mov
2023/02/06 08:07:20 [846943] <f+++++++++ pub/3d/sequence/sq0590/lay/maya/sq0590_lay_sh0112_r002.mov
2023/02/06 08:07:20 [846943] <f+++++++++ pub/3d/sequence/sq0590/lay/maya/sq0590_lay_sh0114_r002.mov
2023/02/06 08:07:20 [846943] <f+++++++++ pub/3d/sequence/sq0590/lay/maya/sq0590_lay_sh0120_r002.mov
2023/02/06 08:11:34 [846943] sent 33986231 bytes  received 23780 bytes  total size 379946073466

Further samples

Here are two further samples to better understand the log structure. The first one is 200514_lestudio_up.log:

2020/05/14 06:23:04 [9055] building file list
2020/05/14 06:23:04 [9055] 8 files to consider
2020/05/14 06:23:04 [9055] .d..t...... 2018-10_MICE_NUKE/COMPOS/SEQ035/SH0025/COMP/WIP/
2020/05/14 06:23:04 [9055] <f+++++++++ 2018-10_MICE_NUKE/COMPOS/SEQ035/SH0025/COMP/WIP/mice_comp_seq035_sh0025_take004_001_mhd.nk
2020/05/14 06:23:04 [9055] <f+++++++++ 2018-10_MICE_NUKE/COMPOS/SEQ035/SH0025/COMP/WIP/mice_comp_seq035_sh0025_take004_001_usr.nk
2020/05/14 06:23:04 [9055] sent 25,354 bytes  received 57 bytes  50,822.00 bytes/sec
2020/05/14 06:23:04 [9055] total size is 74,367  speedup is 2.93
2020/05/14 06:51:30 [16925] building file list
2020/05/14 06:51:30 [16925] 1248 files to consider
2020/05/14 06:51:30 [16925] .d..t...... 2018-10_MICE_NUKE/COMPOS/SEQ035/SH0023/COMP/
2020/05/14 06:51:30 [16925] cd+++++++++ 2018-10_MICE_NUKE/COMPOS/SEQ035/SH0023/COMP/PUBLISH/
2020/05/14 06:51:30 [16925] cd+++++++++ 2018-10_MICE_NUKE/COMPOS/SEQ035/SH0023/COMP/PUBLISH/001/
2020/05/14 06:51:30 [16925] <f+++++++++ 2018-10_MICE_NUKE/COMPOS/SEQ035/SH0023/COMP/PUBLISH/001/mice_comp_seq035_sh0023_take002_001_mhd.nk
2020/05/14 06:51:30 [16925] .d..t...... 2018-10_MICE_NUKE/COMPOS/SEQ035/SH0027/COMP/
2020/05/14 06:51:30 [16925] cd+++++++++ 2018-10_MICE_NUKE/COMPOS/SEQ035/SH0027/COMP/PUBLISH/
2020/05/14 06:51:30 [16925] cd+++++++++ 2018-10_MICE_NUKE/COMPOS/SEQ035/SH0027/COMP/PUBLISH/001/
2020/05/14 06:51:30 [16925] <f+++++++++ 2018-10_MICE_NUKE/COMPOS/SEQ035/SH0027/COMP/PUBLISH/001/mice_comp_seq035_sh0027_take002_001_mhd.nk
2020/05/14 06:51:30 [16925] .d..t...... DATABASE/03_SHOTS/SEQ014B/SH0022/10_RND/01_RENDERS/
2020/05/14 06:51:30 [16925] cd+++++++++ DATABASE/03_SHOTS/SEQ014B/SH0022/10_RND/01_RENDERS/REFLECTION_MASK_02/
2020/05/14 06:51:30 [16925] cd+++++++++ DATABASE/03_SHOTS/SEQ014B/SH0022/10_RND/01_RENDERS/REFLECTION_MASK_02/beauty/
2020/05/14 06:51:30 [16925] <f+++++++++ DATABASE/03_SHOTS/SEQ014B/SH0022/10_RND/01_RENDERS/REFLECTION_MASK_02/beauty/REFLECTION_MASK_02_beauty_1001.exr
2020/05/14 06:51:30 [16925] <f+++++++++ DATABASE/03_SHOTS/SEQ014B/SH0022/10_RND/01_RENDERS/REFLECTION_MASK_02/beauty/REFLECTION_MASK_02_beauty_1002.exr
2020/05/14 06:51:31 [16925] <f+++++++++ DATABASE/03_SHOTS/SEQ014B/SH0022/10_RND/01_RENDERS/REFLECTION_MASK_02/beauty/REFLECTION_MASK_02_beauty_1003.exr
2020/05/14 06:51:31 [16925] <f+++++++++ DATABASE/03_SHOTS/SEQ014B/SH0022/10_RND/01_RENDERS/REFLECTION_MASK_02/beauty/REFLECTION_MASK_02_beauty_1004.exr
2020/05/14 06:51:31 [16925] <f+++++++++ DATABASE/03_SHOTS/SEQ014B/SH0022/10_RND/01_RENDERS/REFLECTION_MASK_02/beauty/REFLECTION_MASK_02_beauty_1005.exr
2020/05/14 06:51:31 [16925] <f+++++++++ DATABASE/03_SHOTS/SEQ014B/SH0022/10_RND/01_RENDERS/REFLECTION_MASK_02/beauty/REFLECTION_MASK_02_beauty_1006.exr
...
2020/05/14 06:52:22 [16925] <f+++++++++ DATABASE/03_SHOTS/SEQ067/SH0028/10_RND/01_RENDERS/OLD/N/PARTICLES_N_1162.exr
2020/05/14 06:52:22 [16925] <f+++++++++ DATABASE/03_SHOTS/SEQ067/SH0028/10_RND/01_RENDERS/OLD/N/PARTICLES_N_1163.exr
2020/05/14 06:52:22 [16925] <f+++++++++ DATABASE/03_SHOTS/SEQ067/SH0028/10_RND/01_RENDERS/OLD/N/PARTICLES_N_1164.exr
2020/05/14 06:52:22 [16925] <f+++++++++ DATABASE/03_SHOTS/SEQ067/SH0028/10_RND/01_RENDERS/OLD/N/PARTICLES_N_1165.exr
2020/05/14 06:52:22 [16925] <f+++++++++ DATABASE/03_SHOTS/SEQ067/SH0028/10_RND/01_RENDERS/OLD/N/PARTICLES_N_1166.exr
2020/05/14 06:52:22 [16925] sent 591,951,568 bytes  received 23,103 bytes  11,064,947.12 bytes/sec
2020/05/14 06:52:22 [16925] total size is 656,568,648  speedup is 1.11

The other, sync_190617_feitong.log contains the details for the last file sent by Feitong:

2019/06/20 13:37:46 [32265] receiving file list
2019/06/20 13:37:47 [32265] 6 files to consider
2019/06/20 13:37:47 [32265] delta-transmission enabled
2019/06/20 13:41:19 [32288] >f.st...... To_Publish/FG/Shot/Shot/Layout-Line/109s2740.psd
2019/06/20 13:41:20 [32288] total: matches=1217 hash_hits=57354 false_alarms=0 data=2242054
2019/06/20 13:41:20 [32288] sent 13,250 bytes received 1,038,733 bytes 4,792.63 bytes/sec
2019/06/20 13:41:20 [32288] total size is 4,879,709 speedup is 4.64

The last transfer was 4,7KB/s (which is very slow and shows that actions may be required to improve the transfer speed).

Transmissions of logs to the connected storages

The log files that are generated on the hub where rsync commands are executed and can be transfered to the storages needing access to these logs like any other file in the project. The following filter rules may be used to transmit all logs to the chosen storage(s):

+ /.syncp/
+ /.syncp/log/***

It is possible to only select one part of the logs by refining the filter rules (e.g. by choosing a specific storage name, a direction, etc).

Making Charts

Extracting data from the rsync transfer logs can be interesting to build charts. Here are two examples built to show the synchronisation uploads for the production of the film Angelo dans la forêt mystérieuse:

Weekly upload chart Daily upload chart

For more information on chart development, check out this blog article.

Please contact us if you need similar charts and the scripts used to generate them for your project.

Navigation

Resources

Partnerships

Contact