[2017/04/11 05:35:21.055643,  6, pid=15814, effective(0, 0), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:2064(shadow_copy2_get_shadow_copy_data)
  shadow_copy2_get_shadow_copy_data: snap2_GMT-2017.04.10-07.40.00 -> @GMT-2017.04.10-07.40.00
[2017/04/11 05:35:21.056054, 10, pid=15814, effective(0, 0), real(0, 0), class=vfs] ../source3/modules/vfs_default.c:1376(vfswrap_fsctl)
  FSCTL_GET_SHADOW_COPY_DATA: 1 volumes for path[2].
  Label[0]: '@GMT-2017.04.10-07.40.00'
[2017/04/11 05:35:21.056112, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_ioctl.c:291(smbd_smb2_request_ioctl_done)
  smbd_smb2_request_ioctl_done: smbd_smb2_ioctl_recv returned 64 status NT_STATUS_OK
[2017/04/11 05:35:21.056136, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:2988(smbd_smb2_request_done_ex)
  smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[48] dyn[yes:64] at ../source3/smbd/smb2_ioctl.c:358
[2017/04/11 05:35:21.056160, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:912(smb2_set_operation_credit)
  smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 386/512, total granted/max/low/range 127/8192/218/127
[2017/04/11 05:35:21.057311, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:3860(smbd_smb2_io_handler)
  smbd_smb2_request idx[1] of 5 vectors
[2017/04/11 05:35:21.057416, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:660(smb2_validate_sequence_number)
  smb2_validate_sequence_number: clearing id 218 (position 218) from bitmap
[2017/04/11 05:35:21.057444, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:2257(smbd_smb2_request_dispatch)
  smbd_smb2_request_dispatch: opcode[SMB2_OP_GETINFO] mid = 218
[2017/04/11 05:35:21.057471,  4, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:384(change_to_user)
  Skipping user change - already user
[2017/04/11 05:35:21.057497, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:1942(smbd_smb2_request_verify_creditcharge)
  mid 218, CreditCharge: 1, NeededCharge: 1
[2017/04/11 05:35:21.057520, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_getinfo.c:272(smbd_smb2_getinfo_send)
  smbd_smb2_getinfo_send: 2 - fnum 1139906581
[2017/04/11 05:35:21.057611, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:605(shadow_copy2_strip_snapshot_internal)
  ../source3/modules/vfs_shadow_copy2.c:605: enter path '2'
[2017/04/11 05:35:21.057645, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:614(shadow_copy2_strip_snapshot_internal)
  ../source3/modules/vfs_shadow_copy2.c:614: abs path '/2'
[2017/04/11 05:35:21.057709, 10, pid=15814, effective(0, 0), real(0, 0), class=locking] ../source3/locking/share_mode_lock.c:283(share_mode_memcache_fetch)
  fetched entry for file 2 seq 0x6134503726815831746 key df8ab18b:a7219f15abd294a8:0
[2017/04/11 05:35:21.057743, 10, pid=15814, effective(0, 0), real(0, 0), class=locking] ../source3/locking/locking.c:1225(find_delete_on_close_token)
  find_delete_on_close_token: name_hash = 0x3d9c523d
[2017/04/11 05:35:21.057767,  5, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/trans2.c:4832(smbd_do_qfilepathinfo)
  smbd_do_qfilepathinfo: 2 (fnum 1139906581) level=1007 max_data=32
[2017/04/11 05:35:21.057823,  8, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/dosmode.c:616(dos_mode)
  dos_mode: 2
[2017/04/11 05:35:21.057848, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:605(shadow_copy2_strip_snapshot_internal)
  ../source3/modules/vfs_shadow_copy2.c:605: enter path '2'
[2017/04/11 05:35:21.057869, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:614(shadow_copy2_strip_snapshot_internal)
  ../source3/modules/vfs_shadow_copy2.c:614: abs path '/2'
[2017/04/11 05:35:21.058025, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/dosmode.c:306(get_ea_dos_attribute)
  get_ea_dos_attribute: 2 attr = 0x10
[2017/04/11 05:35:21.058060, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/dosmode.c:348(get_ea_dos_attribute)
  get_ea_dos_attribute: file 2 case 3 set btime Fri Apr  7 09:37:03 2017
  
[2017/04/11 05:35:21.058093,  5, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print)
  dos_mode_debug_print: get_ea_dos_attribute returning (0x10): "d"
[2017/04/11 05:35:21.058116,  5, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print)
  dos_mode_debug_print: dos_mode returning (0x10): "d"
[2017/04/11 05:35:21.058146, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/trans2.c:5114(smbd_do_qfilepathinfo)
  smbd_do_qfilepathinfo: SMB_FILE_EA_INFORMATION
[2017/04/11 05:35:21.058175, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:2988(smbd_smb2_request_done_ex)
  smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[8] dyn[yes:4] at ../source3/smbd/smb2_getinfo.c:201
[2017/04/11 05:35:21.058202, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:912(smb2_set_operation_credit)
  smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 386/512, total granted/max/low/range 127/8192/219/127
[2017/04/11 05:35:21.061405, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:3860(smbd_smb2_io_handler)
  smbd_smb2_request idx[1] of 5 vectors
[2017/04/11 05:35:21.061472, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:660(smb2_validate_sequence_number)
  smb2_validate_sequence_number: clearing id 219 (position 219) from bitmap
[2017/04/11 05:35:21.061498, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:2257(smbd_smb2_request_dispatch)
  smbd_smb2_request_dispatch: opcode[SMB2_OP_CREATE] mid = 219
[2017/04/11 05:35:21.061524,  4, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:384(change_to_user)
  Skipping user change - already user
[2017/04/11 05:35:21.061562, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_create.c:503(smbd_smb2_create_send)
  smbd_smb2_create: name[2]
[2017/04/11 05:35:21.061593, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_create.c:997(smbd_smb2_create_send)
  smbd_smb2_create_send: open execution phase
[2017/04/11 05:35:21.061616,  5, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/filename.c:443(unix_convert)
  unix_convert called on file "2/@GMT-2017.04.10-07.40.00"
[2017/04/11 05:35:21.061641, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/filename.c:239(rearrange_snapshot_path)
  rearrange_snapshot_path: |2/@GMT-2017.04.10-07.40.00| -> rearrange_snapshot_path: |@GMT-2017.04.10-07.40.00/2|
[2017/04/11 05:35:21.061692, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/statcache.c:245(stat_cache_lookup)
  stat_cache_lookup: lookup failed for name [@GMT-2017.04.10-07.40.00/2]
[2017/04/11 05:35:21.061715, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/statcache.c:245(stat_cache_lookup)
  stat_cache_lookup: lookup failed for name [@GMT-2017.04.10-07.40.00]
[2017/04/11 05:35:21.061735,  5, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/filename.c:644(unix_convert)
  unix_convert begin: name = @GMT-2017.04.10-07.40.00/2, dirpath = , start = @GMT-2017.04.10-07.40.00/2
[2017/04/11 05:35:21.061757, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:605(shadow_copy2_strip_snapshot_internal)
  ../source3/modules/vfs_shadow_copy2.c:605: enter path '@GMT-2017.04.10-07.40.00/2'
[2017/04/11 05:35:21.061779, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:614(shadow_copy2_strip_snapshot_internal)
  ../source3/modules/vfs_shadow_copy2.c:614: abs path '/@GMT-2017.04.10-07.40.00/2'
[2017/04/11 05:35:21.061838, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:730(shadow_copy2_strip_snapshot_internal)
  ../source3/modules/vfs_shadow_copy2.c:730: path '/2' doesn't start with cwd '/
[2017/04/11 05:35:21.061862, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:605(shadow_copy2_strip_snapshot_internal)
  ../source3/modules/vfs_shadow_copy2.c:605: enter path '@GMT-2017.04.10-07.40.00'
[2017/04/11 05:35:21.061883, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:614(shadow_copy2_strip_snapshot_internal)
  ../source3/modules/vfs_shadow_copy2.c:614: abs path '/@GMT-2017.04.10-07.40.00'
[2017/04/11 05:35:21.061904, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:688(shadow_copy2_strip_snapshot_internal)
  ../source3/modules/vfs_shadow_copy2.c:688: path '' doesn't start with cwd '/
[2017/04/11 05:35:21.061924, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/mangle_hash2.c:418(is_mangled)
  is_mangled @GMT-2017.04.10-07.40.00/2 ?
[2017/04/11 05:35:21.061945, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/mangle_hash2.c:357(is_mangled_component)
  is_mangled_component @GMT-2017.04.10-07.40.00/2 (len 24) ?
[2017/04/11 05:35:21.061964, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/mangle_hash2.c:357(is_mangled_component)
  is_mangled_component 2 (len 1) ?
[2017/04/11 05:35:21.061983, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:605(shadow_copy2_strip_snapshot_internal)
  ../source3/modules/vfs_shadow_copy2.c:605: enter path '@GMT-2017.04.10-07.40.00'
[2017/04/11 05:35:21.062003, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:614(shadow_copy2_strip_snapshot_internal)
  ../source3/modules/vfs_shadow_copy2.c:614: abs path '/@GMT-2017.04.10-07.40.00'
[2017/04/11 05:35:21.062023, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:688(shadow_copy2_strip_snapshot_internal)
  ../source3/modules/vfs_shadow_copy2.c:688: path '' doesn't start with cwd '/
[2017/04/11 05:35:21.062043, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/mangle_hash2.c:418(is_mangled)
  is_mangled @GMT-2017.04.10-07.40.00 ?
[2017/04/11 05:35:21.062061, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/mangle_hash2.c:357(is_mangled_component)
  is_mangled_component @GMT-2017.04.10-07.40.00 (len 24) ?
[2017/04/11 05:35:21.062080, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:2525(shadow_copy2_get_real_filename)
  shadow_copy2_get_real_filename called for path=[], name=[@GMT-2017.04.10-07.40.00]
[2017/04/11 05:35:21.062099, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:605(shadow_copy2_strip_snapshot_internal)
  ../source3/modules/vfs_shadow_copy2.c:605: enter path ''
[2017/04/11 05:35:21.062147, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:614(shadow_copy2_strip_snapshot_internal)
  ../source3/modules/vfs_shadow_copy2.c:614: abs path '/'
[2017/04/11 05:35:21.062171, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/modules/vfs_shadow_copy2.c:2533(shadow_copy2_get_real_filename)
  timestamp == 0
[2017/04/11 05:35:21.126502,  5, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/filename.c:913(unix_convert)
  Intermediate not found @GMT-2017.04.10-07.40.00
[2017/04/11 05:35:21.126593, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/filename.c:1191(unix_convert)
  dirpath = [] start = [@GMT-2017.04.10-07.40.00/2]
[2017/04/11 05:35:21.126626, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/filename.c:1596(filename_convert_internal)
  filename_convert_internal: unix_convert failed for name 2/@GMT-2017.04.10-07.40.00 with NT_STATUS_OBJECT_PATH_NOT_FOUND
[2017/04/11 05:35:21.126669,  3, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:3097(smbd_smb2_request_error_ex)
  smbd_smb2_request_error_ex: smbd_smb2_request_error_ex: idx[1] status[NT_STATUS_OBJECT_PATH_NOT_FOUND] || at ../source3/smbd/smb2_create.c:293
[2017/04/11 05:35:21.126697, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:2988(smbd_smb2_request_done_ex)
  smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OBJECT_PATH_NOT_FOUND] body[8] dyn[yes:1] at ../source3/smbd/smb2_server.c:3145
[2017/04/11 05:35:21.126724, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:912(smb2_set_operation_credit)
  smb2_set_operation_credit: requested 1, charge 1, granted 1, current possible/max 386/512, total granted/max/low/range 127/8192/220/127
[2017/04/11 05:35:21.128020, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:3860(smbd_smb2_io_handler)
  smbd_smb2_request idx[1] of 5 vectors
[2017/04/11 05:35:21.128087, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:660(smb2_validate_sequence_number)
  smb2_validate_sequence_number: clearing id 220 (position 220) from bitmap
[2017/04/11 05:35:21.128116, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_server.c:2257(smbd_smb2_request_dispatch)
  smbd_smb2_request_dispatch: opcode[SMB2_OP_CLOSE] mid = 220
[2017/04/11 05:35:21.128149,  4, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:384(change_to_user)
  Skipping user change - already user
[2017/04/11 05:35:21.128185, 10, pid=15814, effective(0, 0), real(0, 0)] ../source3/smbd/smb2_close.c:227(smbd_smb2_close)
  smbd_smb2_close: 2 - fnum 1139906581