Attachment 14320 Details for Bug 13524 – level 10 logs

level 10 logs

log.cosmic-samba-vfs-stack (text/plain), 75.75 KB, created by Andreas Hasenack on 2018-07-11 20:06:52 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Andreas Hasenack

Created: 2018-07-11 20:06:52 UTC

Size: 75.75 KB

patch

obsolete

>[2018/07/11 20:03:14.707487, 10, pid=6945, effective(0, 0), real(0, 0), class=smb2] ../source3/smbd/smb2_server.c:3934(smbd_smb2_io_handler)
>  smbd_smb2_request idx[1] of 5 vectors
>[2018/07/11 20:03:14.707825, 10, pid=6945, effective(0, 0), real(0, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:678(smb2_validate_sequence_number)
>  smb2_validate_sequence_number: smb2_validate_sequence_number: clearing id 241 (position 241) from bitmap
>[2018/07/11 20:03:14.707972, 10, pid=6945, effective(0, 0), real(0, 0), class=smb2] ../source3/smbd/smb2_server.c:2327(smbd_smb2_request_dispatch)
>  smbd_smb2_request_dispatch: opcode[SMB2_OP_CREATE] mid = 241
>[2018/07/11 20:03:14.708126,  4, pid=6945, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
>  setting sec ctx (1000, 1000) - sec_ctx_stack_ndx = 0
>[2018/07/11 20:03:14.708260,  5, pid=6945, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:63(security_token_debug)
>  Security token SIDs (18):
>    SID[  0]: S-1-5-21-974925914-423971577-4012352237-1000
>    SID[  1]: S-1-5-21-974925914-423971577-4012352237-513
>    SID[  2]: S-1-22-2-1000
>    SID[  3]: S-1-22-2-4
>    SID[  4]: S-1-22-2-20
>    SID[  5]: S-1-22-2-24
>    SID[  6]: S-1-22-2-25
>    SID[  7]: S-1-22-2-27
>    SID[  8]: S-1-22-2-29
>    SID[  9]: S-1-22-2-30
>    SID[ 10]: S-1-22-2-44
>    SID[ 11]: S-1-22-2-46
>    SID[ 12]: S-1-22-2-108
>    SID[ 13]: S-1-22-2-114
>    SID[ 14]: S-1-1-0
>    SID[ 15]: S-1-5-2
>    SID[ 16]: S-1-5-11
>    SID[ 17]: S-1-22-1-1000
>   Privileges (0x               0):
>   Rights (0x               0):
>[2018/07/11 20:03:14.708903,  5, pid=6945, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:810(debug_unix_user_token)
>  UNIX token of user 1000
>  Primary group is 1000 and contains 12 supplementary groups
>  Group[  0]: 1000
>  Group[  1]: 4
>  Group[  2]: 20
>  Group[  3]: 24
>  Group[  4]: 25
>  Group[  5]: 27
>  Group[  6]: 29
>  Group[  7]: 30
>  Group[  8]: 44
>  Group[  9]: 46
>  Group[ 10]: 108
>  Group[ 11]: 114
>[2018/07/11 20:03:14.709297,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/uid.c:363(change_to_user_internal)
>  Impersonated user: uid=(1000,1000), gid=(0,1000)
>[2018/07/11 20:03:14.709386, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_create.c:652(smbd_smb2_create_send)
>  smbd_smb2_create_send: name []
>[2018/07/11 20:03:14.709461, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_create.c:750(smbd_smb2_create_send)
>  smbd_smb2_create_send: open execution phase
>[2018/07/11 20:03:14.709530,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/filename.c:461(unix_convert)
>  unix_convert called on file ""
>[2018/07/11 20:03:14.709687,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/filename.c:495(unix_convert)
>  conversion finished "" -> .
>[2018/07/11 20:03:14.709769, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1283(check_reduced_name)
>  check_reduced_name: check_reduced_name [.] [/storage]
>[2018/07/11 20:03:14.709853, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1347(check_reduced_name)
>  check_reduced_name realpath [.] -> [/storage]
>[2018/07/11 20:03:14.709926,  5, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1458(check_reduced_name)
>  check_reduced_name: . reduced to /storage
>[2018/07/11 20:03:14.710000, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:5554(create_file_default)
>  create_file: access_mask = 0x81 file_attributes = 0x10, share_access = 0x3, create_disposition = 0x1 create_options = 0x1 oplock_request = 0x0 private_flags = 0x0 root_dir_fid = 0x0, ea_list = 0x(nil), sd = 0x(nil), fname = .
>[2018/07/11 20:03:14.710080, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:5017(create_file_unixpath)
>  create_file_unixpath: access_mask = 0x81 file_attributes = 0x10, share_access = 0x3, create_disposition = 0x1 create_options = 0x1 oplock_request = 0x0 private_flags = 0x0 ea_list = 0x(nil), sd = 0x(nil), fname = .
>[2018/07/11 20:03:14.710156,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:3945(open_directory)
>  open_directory: opening directory ., access_mask = 0x81, share_access = 0x3 create_options = 0x1, create_disposition = 0x1, file_attributes = 0x10
>[2018/07/11 20:03:14.710234, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:3483(posix_get_nt_acl)
>  posix_get_nt_acl: called for file .
>[2018/07/11 20:03:14.710380, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1286(uid_to_sid)
>  uid 1000 -> sid S-1-5-21-974925914-423971577-4012352237-1000
>[2018/07/11 20:03:14.710471, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1335(gid_to_sid)
>  gid 1000 -> sid S-1-22-2-1000
>[2018/07/11 20:03:14.710549, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2726(canonicalise_acl)
>  canonicalise_acl: Access ace entries before arrange :
>[2018/07/11 20:03:14.710619, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2739(canonicalise_acl)
>  canon_ace index 0. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms r-x
>[2018/07/11 20:03:14.710697, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2739(canonicalise_acl)
>  canon_ace index 1. Type = allow SID = S-1-22-2-1000 gid 1000 SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-x
>[2018/07/11 20:03:14.710772, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2739(canonicalise_acl)
>  canon_ace index 2. Type = allow SID = S-1-5-21-974925914-423971577-4012352237-1000 uid 1000 SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx
>[2018/07/11 20:03:14.710850, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:847(print_canon_ace_list)
>  print_canon_ace_list: canonicalise_acl: ace entries after arrange
>  canon_ace index 0. Type = allow SID = S-1-5-21-974925914-423971577-4012352237-1000 uid 1000 SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx
>  canon_ace index 1. Type = allow SID = S-1-22-2-1000 gid 1000 SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-x
>  canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms r-x
>[2018/07/11 20:03:14.711007, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1111(map_canon_ace_perms)
>  map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff
>[2018/07/11 20:03:14.711079, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1111(map_canon_ace_perms)
>  map_canon_ace_perms: Mapped (UNIX) 140 to (NT) 1200a9
>[2018/07/11 20:03:14.711150, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1111(map_canon_ace_perms)
>  map_canon_ace_perms: Mapped (UNIX) 140 to (NT) 1200a9
>[2018/07/11 20:03:14.711234, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:183(smbd_check_access_rights)
>  smbd_check_access_rights: file . requesting 0x81 returning 0x1 (NT_STATUS_OK)
>[2018/07/11 20:03:14.711322,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:130(dbwrap_lock_order_lock)
>  dbwrap_lock_order_lock: check lock order 1 for /var/run/samba/smbXsrv_open_global.tdb
>[2018/07/11 20:03:14.711343, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:116(debug_lock_order)
>  lock order:  1:/var/run/samba/smbXsrv_open_global.tdb 2:<none> 3:<none>
>[2018/07/11 20:03:14.711364, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key)
>  Locking key 0886D56E
>[2018/07/11 20:03:14.711385, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:145(db_tdb_fetch_locked_internal)
>  Allocated locked data 0x0x564278559d70
>[2018/07/11 20:03:14.711405, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:625(smbXsrv_open_global_verify_record)
>  smbXsrv_open_global_verify_record: empty value
>[2018/07/11 20:03:14.711438, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:744(smbXsrv_open_global_store)
>  smbXsrv_open_global_store: key '0886D56E' stored
>[2018/07/11 20:03:14.711459,  1, pid=6945, effective(1000, 1000), real(1000, 0), class=rpc_parse] ../librpc/ndr/ndr.c:422(ndr_print_debug)
>       &global_blob: struct smbXsrv_open_globalB
>          version                  : SMBXSRV_VERSION_0 (0)
>          seqnum                   : 0x00000001 (1)
>          info                     : union smbXsrv_open_globalU(case 0)
>          info0                    : *
>              info0: struct smbXsrv_open_global0
>                  db_rec                   : *
>                  server_id: struct server_id
>                      pid                      : 0x0000000000001b21 (6945)
>                      task_id                  : 0x00000000 (0)
>                      vnn                      : 0xffffffff (4294967295)
>                      unique_id                : 0xce186dd40ec2e45f (-3596003544907193249)
>                  open_global_id           : 0x0886d56e (143054190)
>                  open_persistent_id       : 0x000000000886d56e (143054190)
>                  open_volatile_id         : 0x00000000c53829ca (3308792266)
>                  open_owner               : S-1-5-21-974925914-423971577-4012352237-1000
>                  open_time                : Wed Jul 11 20:03:15 2018 UTC
>                  create_guid              : 00000000-0000-0000-0000-000000000000
>                  client_guid              : 841545fa-46c0-4b53-94ae-f78a9288a6fe
>                  app_instance_id          : 00000000-0000-0000-0000-000000000000
>                  disconnect_time          : NTTIME(0)
>                  durable_timeout_msec     : 0x00000000 (0)
>                  durable                  : 0x00 (0)
>                  backend_cookie           : DATA_BLOB length=0
>                  channel_sequence         : 0x0000 (0)
>                  channel_generation       : 0x0000000000000000 (0)
>[2018/07/11 20:03:14.711668, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key)
>  Unlocking key 0886D56E
>[2018/07/11 20:03:14.711688,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_lock_order_unlock)
>  dbwrap_lock_order_unlock: release lock order 1 for /var/run/samba/smbXsrv_open_global.tdb
>[2018/07/11 20:03:14.711708, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:911(smbXsrv_open_create)
>  smbXsrv_open_create: global_id (0x0886d56e) stored
>[2018/07/11 20:03:14.711728,  1, pid=6945, effective(1000, 1000), real(1000, 0), class=rpc_parse] ../librpc/ndr/ndr.c:422(ndr_print_debug)
>       &open_blob: struct smbXsrv_openB
>          version                  : SMBXSRV_VERSION_0 (0)
>          reserved                 : 0x00000000 (0)
>          info                     : union smbXsrv_openU(case 0)
>          info0                    : *
>              info0: struct smbXsrv_open
>                  table                    : *
>                  db_rec                   : NULL
>                  local_id                 : 0xc53829ca (3308792266)
>                  global                   : *
>                      global: struct smbXsrv_open_global0
>                          db_rec                   : NULL
>                          server_id: struct server_id
>                              pid                      : 0x0000000000001b21 (6945)
>                              task_id                  : 0x00000000 (0)
>                              vnn                      : 0xffffffff (4294967295)
>                              unique_id                : 0xce186dd40ec2e45f (-3596003544907193249)
>                          open_global_id           : 0x0886d56e (143054190)
>                          open_persistent_id       : 0x000000000886d56e (143054190)
>                          open_volatile_id         : 0x00000000c53829ca (3308792266)
>                          open_owner               : S-1-5-21-974925914-423971577-4012352237-1000
>                          open_time                : Wed Jul 11 20:03:15 2018 UTC
>                          create_guid              : 00000000-0000-0000-0000-000000000000
>                          client_guid              : 841545fa-46c0-4b53-94ae-f78a9288a6fe
>                          app_instance_id          : 00000000-0000-0000-0000-000000000000
>                          disconnect_time          : NTTIME(0)
>                          durable_timeout_msec     : 0x00000000 (0)
>                          durable                  : 0x00 (0)
>                          backend_cookie           : DATA_BLOB length=0
>                          channel_sequence         : 0x0000 (0)
>                          channel_generation       : 0x0000000000000000 (0)
>                  status                   : NT_STATUS_OK
>                  idle_time                : Wed Jul 11 20:03:15 2018 UTC
>                  compat                   : NULL
>                  flags                    : 0x00 (0)
>                         0: SMBXSRV_OPEN_NEED_REPLAY_CACHE
>                         0: SMBXSRV_OPEN_HAVE_REPLAY_CACHE
>                  create_action            : 0x00000000 (0)
>                  request_count            : 0x0000000000000000 (0)
>                  pre_request_count        : 0x0000000000000000 (0)
>[2018/07/11 20:03:14.712026,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:128(file_new)
>  allocated file structure fnum 3308792266 (1 used)
>[2018/07/11 20:03:14.712051, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:754(file_name_hash)
>  file_name_hash: /storage/. hash 0x83de38f3
>[2018/07/11 20:03:14.712078, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1283(check_reduced_name)
>  check_reduced_name: check_reduced_name [.] [/storage]
>[2018/07/11 20:03:14.712102, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1347(check_reduced_name)
>  check_reduced_name realpath [.] -> [/storage]
>[2018/07/11 20:03:14.712122,  5, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1458(check_reduced_name)
>  check_reduced_name: . reduced to /storage
>[2018/07/11 20:03:14.712147, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:767(fd_open)
>  fd_open: name ., flags = 0200000 mode = 00, fd = 32. 
>[2018/07/11 20:03:14.712171,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:130(dbwrap_lock_order_lock)
>  dbwrap_lock_order_lock: check lock order 1 for /var/run/samba/locking.tdb
>[2018/07/11 20:03:14.712191, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:116(debug_lock_order)
>  lock order:  1:/var/run/samba/locking.tdb 2:<none> 3:<none>
>[2018/07/11 20:03:14.712212, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key)
>  Locking key 7000000000000000A3A7
>[2018/07/11 20:03:14.712232, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:145(db_tdb_fetch_locked_internal)
>  Allocated locked data 0x0x564278539430
>[2018/07/11 20:03:14.712255, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:368(unparse_share_modes)
>  unparse_share_modes:
>[2018/07/11 20:03:14.712275,  1, pid=6945, effective(1000, 1000), real(1000, 0), class=rpc_parse] ../librpc/ndr/ndr.c:422(ndr_print_debug)
>       d: struct share_mode_data
>          sequence_number          : 0xc62a61f1220a0920 (-4167410816891877088)
>          servicepath              : *
>              servicepath              : '/storage'
>          base_name                : *
>              base_name                : '.'
>          stream_name              : NULL
>          num_share_modes          : 0x00000001 (1)
>          share_modes: ARRAY(1)
>              share_modes: struct share_mode_entry
>                  pid: struct server_id
>                      pid                      : 0x0000000000001b21 (6945)
>                      task_id                  : 0x00000000 (0)
>                      vnn                      : 0xffffffff (4294967295)
>                      unique_id                : 0xce186dd40ec2e45f (-3596003544907193249)
>                  op_mid                   : 0x00000000000000f1 (241)
>                  op_type                  : 0x0000 (0)
>                  lease_idx                : 0xffffffff (4294967295)
>                  access_mask              : 0x00000081 (129)
>                  share_access             : 0x00000003 (3)
>                  private_options          : 0x00000000 (0)
>                  time                     : Wed Jul 11 20:03:14 2018 UTC.711317
>                  id: struct file_id
>                      devid                    : 0x0000000000000070 (112)
>                      inode                    : 0x000000000000a7a3 (42915)
>                      extid                    : 0x0000000000000000 (0)
>                  share_file_id            : 0x0000000075021510 (1963070736)
>                  uid                      : 0x000003e8 (1000)
>                  flags                    : 0x0000 (0)
>                  name_hash                : 0x83de38f3 (2212378867)
>                  stale                    : 0x00 (0)
>                  lease                    : NULL
>          num_leases               : 0x00000000 (0)
>          leases: ARRAY(0)
>          num_delete_tokens        : 0x00000000 (0)
>          delete_tokens: ARRAY(0)
>          old_write_time           : Thu Jan  1 00:00:00 1970 UTC.0
>          changed_write_time       : Thu Jan  1 00:00:00 1970 UTC.0
>          fresh                    : 0x01 (1)
>          modified                 : 0x01 (1)
>          record                   : *
>          id: struct file_id
>              devid                    : 0x0000000000000070 (112)
>              inode                    : 0x000000000000a7a3 (42915)
>              extid                    : 0x0000000000000000 (0)
>[2018/07/11 20:03:14.712606, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:157(share_mode_memcache_delete)
>  deleting entry for file . seq 0x14279333256817674528 key 70:a7a3:0
>[2018/07/11 20:03:14.712635,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_lock_order_unlock)
>  dbwrap_lock_order_unlock: release lock order 1 for /var/run/samba/locking.tdb
>[2018/07/11 20:03:14.712657, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key)
>  Unlocking key 7000000000000000A3A7
>[2018/07/11 20:03:14.712677, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:171(share_mode_memcache_store)
>  stored entry for file . seq 0x14279333256817674529 key 70:a7a3:0
>[2018/07/11 20:03:14.712698, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:5363(create_file_unixpath)
>  create_file_unixpath: info=1
>[2018/07/11 20:03:14.712717, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:5642(create_file_default)
>  create_file: info=1
>[2018/07/11 20:03:14.712737, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_create.c:1281(smbd_smb2_create_after_exec)
>  smbd_smb2_create_send: response construction phase
>[2018/07/11 20:03:14.712757,  8, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:667(dos_mode)
>  dos_mode: .
>[2018/07/11 20:03:14.712778,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print)
>  dos_mode_debug_print: dos_mode_from_sbuf returning (0x10): "d"
>[2018/07/11 20:03:14.712799,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print)
>  dos_mode_debug_print: dos_mode returning (0x10): "d"
>[2018/07/11 20:03:14.712819, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_create.c:1507(smbd_smb2_create_finish)
>  smbd_smb2_create_finish: . - fnum 3308792266
>[2018/07/11 20:03:14.712842, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:3062(smbd_smb2_request_done_ex)
>  smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[88] dyn[yes:0] at ../source3/smbd/smb2_create.c:367
>[2018/07/11 20:03:14.712864, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:936(smb2_set_operation_credit)
>  smb2_set_operation_credit: smb2_set_operation_credit: requested 7681, charge 1, granted 1, current possible/max 1/512, total granted/max/low/range 512/8192/242/512
>[2018/07/11 20:03:14.713001, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:3934(smbd_smb2_io_handler)
>  smbd_smb2_request idx[1] of 5 vectors
>[2018/07/11 20:03:14.713028, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:678(smb2_validate_sequence_number)
>  smb2_validate_sequence_number: smb2_validate_sequence_number: clearing id 242 (position 242) from bitmap
>[2018/07/11 20:03:14.713048, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:2327(smbd_smb2_request_dispatch)
>  smbd_smb2_request_dispatch: opcode[SMB2_OP_QUERY_DIRECTORY] mid = 242
>[2018/07/11 20:03:14.713069,  4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/uid.c:384(change_to_user)
>  Skipping user change - already user
>[2018/07/11 20:03:14.713089, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_query_directory.c:97(smbd_smb2_request_process_query_directory)
>  smbd_smb2_request_find_done: in_output_buffer_length = 65535
>[2018/07/11 20:03:14.713111, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_query_directory.c:263(smbd_smb2_query_directory_send)
>  smbd_smb2_query_directory_send: . - fnum 3308792266
>[2018/07/11 20:03:14.713132, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:1997(smbd_smb2_request_verify_creditcharge)
>  smbd_smb2_request_verify_creditcharge: mid 242, CreditCharge: 1, NeededCharge: 1
>[2018/07/11 20:03:14.713154,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/filename.c:461(unix_convert)
>  unix_convert called on file "apt-cdrom"
>[2018/07/11 20:03:14.713175, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/statcache.c:245(stat_cache_lookup)
>  stat_cache_lookup: lookup failed for name [APT-CDROM]
>[2018/07/11 20:03:14.713196,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/filename.c:662(unix_convert)
>  unix_convert begin: name = apt-cdrom, dirpath = , start = apt-cdrom
>[2018/07/11 20:03:14.713221,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/statcache.c:144(stat_cache_add)
>  stat_cache_add: Added entry (56427852c940:size 9) APT-CDROM -> apt-cdrom
>[2018/07/11 20:03:14.713241,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/filename.c:685(unix_convert)
>  conversion of base_name finished apt-cdrom -> apt-cdrom
>[2018/07/11 20:03:14.713261, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1283(check_reduced_name)
>  check_reduced_name: check_reduced_name [apt-cdrom] [/storage]
>[2018/07/11 20:03:14.713285, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1347(check_reduced_name)
>  check_reduced_name realpath [apt-cdrom] -> [/storage/apt-cdrom]
>[2018/07/11 20:03:14.713305,  5, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1458(check_reduced_name)
>  check_reduced_name: apt-cdrom reduced to /storage/apt-cdrom
>[2018/07/11 20:03:14.713325,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dir.c:475(dptr_create)
>  dptr_create dir=.
>[2018/07/11 20:03:14.713350,  3, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dir.c:657(dptr_create)
>  creating new dirptr 0 for path ., expect_close = 0
>[2018/07/11 20:03:14.713382,  8, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_query_directory.c:470(smbd_smb2_query_directory_send)
>  smbd_smb2_query_directory_send: dirpath=<.> dontdescend=<>, in_output_buffer_length = 65527
>[2018/07/11 20:03:14.713414,  6, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dir.c:1129(smbd_dirptr_get_entry)
>  smbd_dirptr_get_entry: dirptr 0x56427855d480 now at offset -1
>[2018/07/11 20:03:14.713436,  8, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:667(dos_mode)
>  dos_mode: apt-cdrom
>[2018/07/11 20:03:14.713458,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print)
>  dos_mode_debug_print: dos_mode_from_sbuf returning (0x20): "a"
>[2018/07/11 20:03:14.713478,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print)
>  dos_mode_debug_print: dos_mode returning (0x20): "a"
>[2018/07/11 20:03:14.713500,  3, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dir.c:1220(smbd_dirptr_get_entry)
>  smbd_dirptr_get_entry mask=[apt-cdrom] found apt-cdrom fname=apt-cdrom (apt-cdrom)
>[2018/07/11 20:03:14.713522, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/trans2.c:1842(smbd_marshall_dir_entry)
>  smbd_marshall_dir_entry: space_remaining = 65527
>[2018/07/11 20:03:14.713543, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/trans2.c:2247(smbd_marshall_dir_entry)
>  smbd_marshall_dir_entry: SMB_FIND_ID_BOTH_DIRECTORY_INFO
>[2018/07/11 20:03:14.713573, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/mangle_hash2.c:791(hash2_name_to_8_3)
>  hash2_name_to_8_3: apt-cdrom -> 659FA53C -> AS738L~8 (cache=1)
>[2018/07/11 20:03:14.713597,  6, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dir.c:1129(smbd_dirptr_get_entry)
>  smbd_dirptr_get_entry: dirptr 0x56427855d480 now at offset -1
>[2018/07/11 20:03:14.713619, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_query_directory.c:187(smbd_smb2_request_find_done)
>  smbd_smb2_request_find_done: out_output_buffer.length = 122
>[2018/07/11 20:03:14.713639, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:3062(smbd_smb2_request_done_ex)
>  smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[8] dyn[yes:122] at ../source3/smbd/smb2_query_directory.c:191
>[2018/07/11 20:03:14.713660, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:936(smb2_set_operation_credit)
>  smb2_set_operation_credit: smb2_set_operation_credit: requested 7681, charge 1, granted 1, current possible/max 1/512, total granted/max/low/range 512/8192/243/512
>[2018/07/11 20:03:14.713788, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:3934(smbd_smb2_io_handler)
>  smbd_smb2_request idx[1] of 5 vectors
>[2018/07/11 20:03:14.713813, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:678(smb2_validate_sequence_number)
>  smb2_validate_sequence_number: smb2_validate_sequence_number: clearing id 243 (position 243) from bitmap
>[2018/07/11 20:03:14.713834, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:2327(smbd_smb2_request_dispatch)
>  smbd_smb2_request_dispatch: opcode[SMB2_OP_CREATE] mid = 243
>[2018/07/11 20:03:14.713854,  4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/uid.c:384(change_to_user)
>  Skipping user change - already user
>[2018/07/11 20:03:14.713876, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_create.c:652(smbd_smb2_create_send)
>  smbd_smb2_create_send: name [apt-cdrom]
>[2018/07/11 20:03:14.713897, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_create.c:750(smbd_smb2_create_send)
>  smbd_smb2_create_send: open execution phase
>[2018/07/11 20:03:14.713918,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/filename.c:461(unix_convert)
>  unix_convert called on file "apt-cdrom"
>[2018/07/11 20:03:14.713938, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/statcache.c:284(stat_cache_lookup)
>  stat_cache_lookup: lookup succeeded for name [APT-CDROM] -> [apt-cdrom]
>[2018/07/11 20:03:14.713960, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1283(check_reduced_name)
>  check_reduced_name: check_reduced_name [apt-cdrom] [/storage]
>[2018/07/11 20:03:14.713984, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1347(check_reduced_name)
>  check_reduced_name realpath [apt-cdrom] -> [/storage/apt-cdrom]
>[2018/07/11 20:03:14.714004,  5, pid=6945, effective(1000, 1000), real(1000, 0), class=vfs] ../source3/smbd/vfs.c:1458(check_reduced_name)
>  check_reduced_name: apt-cdrom reduced to /storage/apt-cdrom
>[2018/07/11 20:03:14.714023, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:5554(create_file_default)
>  create_file: access_mask = 0x10000 file_attributes = 0x80, share_access = 0x7, create_disposition = 0x1 create_options = 0x1000 oplock_request = 0x0 private_flags = 0x0 root_dir_fid = 0x0, ea_list = 0x(nil), sd = 0x(nil), fname = apt-cdrom
>[2018/07/11 20:03:14.714045, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:5017(create_file_unixpath)
>  create_file_unixpath: access_mask = 0x10000 file_attributes = 0x80, share_access = 0x7, create_disposition = 0x1 create_options = 0x1000 oplock_request = 0x0 private_flags = 0x0 ea_list = 0x(nil), sd = 0x(nil), fname = apt-cdrom
>[2018/07/11 20:03:14.714068,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:130(dbwrap_lock_order_lock)
>  dbwrap_lock_order_lock: check lock order 1 for /var/run/samba/smbXsrv_open_global.tdb
>[2018/07/11 20:03:14.714088, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:116(debug_lock_order)
>  lock order:  1:/var/run/samba/smbXsrv_open_global.tdb 2:<none> 3:<none>
>[2018/07/11 20:03:14.714109, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key)
>  Locking key C7B9C9E0
>[2018/07/11 20:03:14.714130, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:145(db_tdb_fetch_locked_internal)
>  Allocated locked data 0x0x56427855f360
>[2018/07/11 20:03:14.714149, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:625(smbXsrv_open_global_verify_record)
>  smbXsrv_open_global_verify_record: empty value
>[2018/07/11 20:03:14.714175, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:744(smbXsrv_open_global_store)
>  smbXsrv_open_global_store: key 'C7B9C9E0' stored
>[2018/07/11 20:03:14.714197,  1, pid=6945, effective(1000, 1000), real(1000, 0), class=rpc_parse] ../librpc/ndr/ndr.c:422(ndr_print_debug)
>       &global_blob: struct smbXsrv_open_globalB
>          version                  : SMBXSRV_VERSION_0 (0)
>          seqnum                   : 0x00000001 (1)
>          info                     : union smbXsrv_open_globalU(case 0)
>          info0                    : *
>              info0: struct smbXsrv_open_global0
>                  db_rec                   : *
>                  server_id: struct server_id
>                      pid                      : 0x0000000000001b21 (6945)
>                      task_id                  : 0x00000000 (0)
>                      vnn                      : 0xffffffff (4294967295)
>                      unique_id                : 0xce186dd40ec2e45f (-3596003544907193249)
>                  open_global_id           : 0xc7b9c9e0 (3350841824)
>                  open_persistent_id       : 0x00000000c7b9c9e0 (3350841824)
>                  open_volatile_id         : 0x00000000faef7f17 (4209999639)
>                  open_owner               : S-1-5-21-974925914-423971577-4012352237-1000
>                  open_time                : Wed Jul 11 20:03:15 2018 UTC
>                  create_guid              : 00000000-0000-0000-0000-000000000000
>                  client_guid              : 841545fa-46c0-4b53-94ae-f78a9288a6fe
>                  app_instance_id          : 00000000-0000-0000-0000-000000000000
>                  disconnect_time          : NTTIME(0)
>                  durable_timeout_msec     : 0x00000000 (0)
>                  durable                  : 0x00 (0)
>                  backend_cookie           : DATA_BLOB length=0
>                  channel_sequence         : 0x0000 (0)
>                  channel_generation       : 0x0000000000000000 (0)
>[2018/07/11 20:03:14.714400, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key)
>  Unlocking key C7B9C9E0
>[2018/07/11 20:03:14.714420,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_lock_order_unlock)
>  dbwrap_lock_order_unlock: release lock order 1 for /var/run/samba/smbXsrv_open_global.tdb
>[2018/07/11 20:03:14.714440, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/smbXsrv_open.c:911(smbXsrv_open_create)
>  smbXsrv_open_create: global_id (0xc7b9c9e0) stored
>[2018/07/11 20:03:14.714459,  1, pid=6945, effective(1000, 1000), real(1000, 0), class=rpc_parse] ../librpc/ndr/ndr.c:422(ndr_print_debug)
>       &open_blob: struct smbXsrv_openB
>          version                  : SMBXSRV_VERSION_0 (0)
>          reserved                 : 0x00000000 (0)
>          info                     : union smbXsrv_openU(case 0)
>          info0                    : *
>              info0: struct smbXsrv_open
>                  table                    : *
>                  db_rec                   : NULL
>                  local_id                 : 0xfaef7f17 (4209999639)
>                  global                   : *
>                      global: struct smbXsrv_open_global0
>                          db_rec                   : NULL
>                          server_id: struct server_id
>                              pid                      : 0x0000000000001b21 (6945)
>                              task_id                  : 0x00000000 (0)
>                              vnn                      : 0xffffffff (4294967295)
>                              unique_id                : 0xce186dd40ec2e45f (-3596003544907193249)
>                          open_global_id           : 0xc7b9c9e0 (3350841824)
>                          open_persistent_id       : 0x00000000c7b9c9e0 (3350841824)
>                          open_volatile_id         : 0x00000000faef7f17 (4209999639)
>                          open_owner               : S-1-5-21-974925914-423971577-4012352237-1000
>                          open_time                : Wed Jul 11 20:03:15 2018 UTC
>                          create_guid              : 00000000-0000-0000-0000-000000000000
>                          client_guid              : 841545fa-46c0-4b53-94ae-f78a9288a6fe
>                          app_instance_id          : 00000000-0000-0000-0000-000000000000
>                          disconnect_time          : NTTIME(0)
>                          durable_timeout_msec     : 0x00000000 (0)
>                          durable                  : 0x00 (0)
>                          backend_cookie           : DATA_BLOB length=0
>                          channel_sequence         : 0x0000 (0)
>                          channel_generation       : 0x0000000000000000 (0)
>                  status                   : NT_STATUS_OK
>                  idle_time                : Wed Jul 11 20:03:15 2018 UTC
>                  compat                   : NULL
>                  flags                    : 0x00 (0)
>                         0: SMBXSRV_OPEN_NEED_REPLAY_CACHE
>                         0: SMBXSRV_OPEN_HAVE_REPLAY_CACHE
>                  create_action            : 0x00000000 (0)
>                  request_count            : 0x0000000000000000 (0)
>                  pre_request_count        : 0x0000000000000000 (0)
>[2018/07/11 20:03:14.714754,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:128(file_new)
>  allocated file structure fnum 4209999639 (2 used)
>[2018/07/11 20:03:14.714776, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:754(file_name_hash)
>  file_name_hash: /storage/apt-cdrom hash 0x421ed6b5
>[2018/07/11 20:03:14.714797,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:206(unix_mode)
>  unix_mode: unix_mode(apt-cdrom) returning 0744
>[2018/07/11 20:03:14.714817, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:2994(open_file_ntcreate)
>  open_file_ntcreate: fname=apt-cdrom, dos_attrs=0x80 access_mask=0x10000 share_access=0x7 create_disposition = 0x1 create_options=0x1000 unix mode=0744 oplock_request=0 private_flags = 0x0
>[2018/07/11 20:03:14.714839, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:3164(open_file_ntcreate)
>  open_file_ntcreate: fname=apt-cdrom, after mapping access_mask=0x10000
>[2018/07/11 20:03:14.714860,  4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:3253(open_file_ntcreate)
>  calling open_file with flags=0x0 flags2=0x0 mode=0744, access_mask = 0x10000, open_access_mask = 0x10000
>[2018/07/11 20:03:14.714881, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:3483(posix_get_nt_acl)
>  posix_get_nt_acl: called for file apt-cdrom
>[2018/07/11 20:03:14.714914, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1286(uid_to_sid)
>  uid 0 -> sid S-1-22-1-0
>[2018/07/11 20:03:14.714939, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1335(gid_to_sid)
>  gid 0 -> sid S-1-22-2-0
>[2018/07/11 20:03:14.714961, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2726(canonicalise_acl)
>  canonicalise_acl: Access ace entries before arrange :
>[2018/07/11 20:03:14.714980, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2739(canonicalise_acl)
>  canon_ace index 0. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms r-x
>[2018/07/11 20:03:14.715002, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2739(canonicalise_acl)
>  canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-x
>[2018/07/11 20:03:14.715023, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2739(canonicalise_acl)
>  canon_ace index 2. Type = allow SID = S-1-22-1-0 uid 0 SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx
>[2018/07/11 20:03:14.715044, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:847(print_canon_ace_list)
>  print_canon_ace_list: canonicalise_acl: ace entries after arrange
>  canon_ace index 0. Type = allow SID = S-1-22-1-0 uid 0 SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx
>  canon_ace index 1. Type = allow SID = S-1-22-2-0 gid 0 SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-x
>  canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms r-x
>[2018/07/11 20:03:14.715086, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1111(map_canon_ace_perms)
>  map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1e01ff
>[2018/07/11 20:03:14.715106, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1111(map_canon_ace_perms)
>  map_canon_ace_perms: Mapped (UNIX) 140 to (NT) 1200a9
>[2018/07/11 20:03:14.715125, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1111(map_canon_ace_perms)
>  map_canon_ace_perms: Mapped (UNIX) 140 to (NT) 1200a9
>[2018/07/11 20:03:14.715147, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:183(smbd_check_access_rights)
>  smbd_check_access_rights: file apt-cdrom requesting 0x10000 returning 0x10000 (NT_STATUS_ACCESS_DENIED)
>[2018/07/11 20:03:14.715169, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:188(smbd_check_access_rights)
>  smbd_check_access_rights: acl for apt-cdrom is:
>[2018/07/11 20:03:14.715188,  1, pid=6945, effective(1000, 1000), real(1000, 0), class=rpc_parse] ../librpc/ndr/ndr.c:422(ndr_print_debug)
>       sd: struct security_descriptor
>          revision                 : SECURITY_DESCRIPTOR_REVISION_1 (1)
>          type                     : 0x9004 (36868)
>                 0: SEC_DESC_OWNER_DEFAULTED 
>                 0: SEC_DESC_GROUP_DEFAULTED 
>                 1: SEC_DESC_DACL_PRESENT    
>                 0: SEC_DESC_DACL_DEFAULTED  
>                 0: SEC_DESC_SACL_PRESENT    
>                 0: SEC_DESC_SACL_DEFAULTED  
>                 0: SEC_DESC_DACL_TRUSTED    
>                 0: SEC_DESC_SERVER_SECURITY 
>                 0: SEC_DESC_DACL_AUTO_INHERIT_REQ
>                 0: SEC_DESC_SACL_AUTO_INHERIT_REQ
>                 0: SEC_DESC_DACL_AUTO_INHERITED
>                 0: SEC_DESC_SACL_AUTO_INHERITED
>                 1: SEC_DESC_DACL_PROTECTED  
>                 0: SEC_DESC_SACL_PROTECTED  
>                 0: SEC_DESC_RM_CONTROL_VALID
>                 1: SEC_DESC_SELF_RELATIVE   
>          owner_sid                : *
>              owner_sid                : S-1-22-1-0
>          group_sid                : *
>              group_sid                : S-1-22-2-0
>          sacl                     : NULL
>          dacl                     : *
>              dacl: struct security_acl
>                  revision                 : SECURITY_ACL_REVISION_NT4 (2)
>                  size                     : 0x004c (76)
>                  num_aces                 : 0x00000003 (3)
>                  aces: ARRAY(3)
>                      aces: struct security_ace
>                          type                     : SEC_ACE_TYPE_ACCESS_ALLOWED (0)
>                          flags                    : 0x00 (0)
>                                 0: SEC_ACE_FLAG_OBJECT_INHERIT
>                                 0: SEC_ACE_FLAG_CONTAINER_INHERIT
>                                 0: SEC_ACE_FLAG_NO_PROPAGATE_INHERIT
>                                 0: SEC_ACE_FLAG_INHERIT_ONLY
>                                 0: SEC_ACE_FLAG_INHERITED_ACE
>                              0x00: SEC_ACE_FLAG_VALID_INHERIT (0)
>                                 0: SEC_ACE_FLAG_SUCCESSFUL_ACCESS
>                                 0: SEC_ACE_FLAG_FAILED_ACCESS
>                          size                     : 0x0018 (24)
>                          access_mask              : 0x001e01ff (1966591)
>                          object                   : union security_ace_object_ctr(case 0)
>                          trustee                  : S-1-22-1-0
>                      aces: struct security_ace
>                          type                     : SEC_ACE_TYPE_ACCESS_ALLOWED (0)
>                          flags                    : 0x00 (0)
>                                 0: SEC_ACE_FLAG_OBJECT_INHERIT
>                                 0: SEC_ACE_FLAG_CONTAINER_INHERIT
>                                 0: SEC_ACE_FLAG_NO_PROPAGATE_INHERIT
>                                 0: SEC_ACE_FLAG_INHERIT_ONLY
>                                 0: SEC_ACE_FLAG_INHERITED_ACE
>                              0x00: SEC_ACE_FLAG_VALID_INHERIT (0)
>                                 0: SEC_ACE_FLAG_SUCCESSFUL_ACCESS
>                                 0: SEC_ACE_FLAG_FAILED_ACCESS
>                          size                     : 0x0018 (24)
>                          access_mask              : 0x001200a9 (1179817)
>                          object                   : union security_ace_object_ctr(case 0)
>                          trustee                  : S-1-22-2-0
>                      aces: struct security_ace
>                          type                     : SEC_ACE_TYPE_ACCESS_ALLOWED (0)
>                          flags                    : 0x00 (0)
>                                 0: SEC_ACE_FLAG_OBJECT_INHERIT
>                                 0: SEC_ACE_FLAG_CONTAINER_INHERIT
>                                 0: SEC_ACE_FLAG_NO_PROPAGATE_INHERIT
>                                 0: SEC_ACE_FLAG_INHERIT_ONLY
>                                 0: SEC_ACE_FLAG_INHERITED_ACE
>                              0x00: SEC_ACE_FLAG_VALID_INHERIT (0)
>                                 0: SEC_ACE_FLAG_SUCCESSFUL_ACCESS
>                                 0: SEC_ACE_FLAG_FAILED_ACCESS
>                          size                     : 0x0014 (20)
>                          access_mask              : 0x001200a9 (1179817)
>                          object                   : union security_ace_object_ctr(case 0)
>                          trustee                  : S-1-1-0
>[2018/07/11 20:03:14.715711, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:3483(posix_get_nt_acl)
>  posix_get_nt_acl: called for file .
>[2018/07/11 20:03:14.715743, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1286(uid_to_sid)
>  uid 1000 -> sid S-1-5-21-974925914-423971577-4012352237-1000
>[2018/07/11 20:03:14.715766, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/passdb/lookup_sid.c:1335(gid_to_sid)
>  gid 1000 -> sid S-1-22-2-1000
>[2018/07/11 20:03:14.715788, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2726(canonicalise_acl)
>  canonicalise_acl: Access ace entries before arrange :
>[2018/07/11 20:03:14.715807, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2739(canonicalise_acl)
>  canon_ace index 0. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms r-x
>[2018/07/11 20:03:14.715828, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2739(canonicalise_acl)
>  canon_ace index 1. Type = allow SID = S-1-22-2-1000 gid 1000 SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-x
>[2018/07/11 20:03:14.715849, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:2739(canonicalise_acl)
>  canon_ace index 2. Type = allow SID = S-1-5-21-974925914-423971577-4012352237-1000 uid 1000 SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx
>[2018/07/11 20:03:14.715871, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:847(print_canon_ace_list)
>  print_canon_ace_list: canonicalise_acl: ace entries after arrange
>  canon_ace index 0. Type = allow SID = S-1-5-21-974925914-423971577-4012352237-1000 uid 1000 SMB_ACL_USER_OBJ ace_flags = 0x0 perms rwx
>  canon_ace index 1. Type = allow SID = S-1-22-2-1000 gid 1000 SMB_ACL_GROUP_OBJ ace_flags = 0x0 perms r-x
>  canon_ace index 2. Type = allow SID = S-1-1-0 other SMB_ACL_OTHER ace_flags = 0x0 perms r-x
>[2018/07/11 20:03:14.715913, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1111(map_canon_ace_perms)
>  map_canon_ace_perms: Mapped (UNIX) 1c0 to (NT) 1f01ff
>[2018/07/11 20:03:14.715933, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1111(map_canon_ace_perms)
>  map_canon_ace_perms: Mapped (UNIX) 140 to (NT) 1200a9
>[2018/07/11 20:03:14.715952, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=acls] ../source3/smbd/posix_acls.c:1111(map_canon_ace_perms)
>  map_canon_ace_perms: Mapped (UNIX) 140 to (NT) 1200a9
>[2018/07/11 20:03:14.715973, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:183(smbd_check_access_rights)
>  smbd_check_access_rights: file . requesting 0x40 returning 0x40 (NT_STATUS_OK)
>[2018/07/11 20:03:14.715994, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:238(smbd_check_access_rights)
>  smbd_check_access_rights: overrode DELETE_ACCESS on file apt-cdrom
>[2018/07/11 20:03:14.716015,  2, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:1404(open_file)
>  ubuntu opened file apt-cdrom read=No write=No (numopen=2)
>[2018/07/11 20:03:14.716036,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:130(dbwrap_lock_order_lock)
>  dbwrap_lock_order_lock: check lock order 1 for /var/run/samba/locking.tdb
>[2018/07/11 20:03:14.716055, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:116(debug_lock_order)
>  lock order:  1:/var/run/samba/locking.tdb 2:<none> 3:<none>
>[2018/07/11 20:03:14.716077, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key)
>  Locking key 700000000000000073AA
>[2018/07/11 20:03:14.716097, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:145(db_tdb_fetch_locked_internal)
>  Allocated locked data 0x0x564278578d90
>[2018/07/11 20:03:14.716120, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:2050(brl_get_locks_readonly)
>  seqnum=0, fsp->brlock_seqnum=0
>[2018/07/11 20:03:14.716143,  5, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/smbd/oplock.c:89(set_file_oplock)
>  set_file_oplock: granted oplock on file apt-cdrom, 70:aa73:0/1803758515, tv_sec = 5b466282, tv_usec = ae552
>[2018/07/11 20:03:14.716165, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/brlock.c:2050(brl_get_locks_readonly)
>  seqnum=0, fsp->brlock_seqnum=0
>[2018/07/11 20:03:14.716184, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:2273(grant_fsp_oplock_type)
>  grant_fsp_oplock_type: oplock type 0x0 on file apt-cdrom
>[2018/07/11 20:03:14.716204, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:368(unparse_share_modes)
>  unparse_share_modes:
>[2018/07/11 20:03:14.716224,  1, pid=6945, effective(1000, 1000), real(1000, 0), class=rpc_parse] ../librpc/ndr/ndr.c:422(ndr_print_debug)
>       d: struct share_mode_data
>          sequence_number          : 0xf2e47d581406c681 (-944492204594379135)
>          servicepath              : *
>              servicepath              : '/storage'
>          base_name                : *
>              base_name                : 'apt-cdrom'
>          stream_name              : NULL
>          num_share_modes          : 0x00000001 (1)
>          share_modes: ARRAY(1)
>              share_modes: struct share_mode_entry
>                  pid: struct server_id
>                      pid                      : 0x0000000000001b21 (6945)
>                      task_id                  : 0x00000000 (0)
>                      vnn                      : 0xffffffff (4294967295)
>                      unique_id                : 0xce186dd40ec2e45f (-3596003544907193249)
>                  op_mid                   : 0x00000000000000f3 (243)
>                  op_type                  : 0x0000 (0)
>                  lease_idx                : 0xffffffff (4294967295)
>                  access_mask              : 0x00010000 (65536)
>                  share_access             : 0x00000007 (7)
>                  private_options          : 0x00000000 (0)
>                  time                     : Wed Jul 11 20:03:14 2018 UTC.714066
>                  id: struct file_id
>                      devid                    : 0x0000000000000070 (112)
>                      inode                    : 0x000000000000aa73 (43635)
>                      extid                    : 0x0000000000000000 (0)
>                  share_file_id            : 0x000000006b832bb3 (1803758515)
>                  uid                      : 0x000003e8 (1000)
>                  flags                    : 0x0000 (0)
>                  name_hash                : 0x421ed6b5 (1109317301)
>                  stale                    : 0x00 (0)
>                  lease                    : NULL
>          num_leases               : 0x00000000 (0)
>          leases: ARRAY(0)
>          num_delete_tokens        : 0x00000000 (0)
>          delete_tokens: ARRAY(0)
>          old_write_time           : Wed Jul 11 19:46:34 2018 UTC.432775009
>          changed_write_time       : Thu Jan  1 00:00:00 1970 UTC.0
>          fresh                    : 0x01 (1)
>          modified                 : 0x01 (1)
>          record                   : *
>          id: struct file_id
>              devid                    : 0x0000000000000070 (112)
>              inode                    : 0x000000000000aa73 (43635)
>              extid                    : 0x0000000000000000 (0)
>[2018/07/11 20:03:14.716556, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:157(share_mode_memcache_delete)
>  deleting entry for file apt-cdrom seq 0x17502251869115172481 key 70:aa73:0
>[2018/07/11 20:03:14.716586,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_lock_order_unlock)
>  dbwrap_lock_order_unlock: release lock order 1 for /var/run/samba/locking.tdb
>[2018/07/11 20:03:14.716608, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key)
>  Unlocking key 700000000000000073AA
>[2018/07/11 20:03:14.716627, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:171(share_mode_memcache_store)
>  stored entry for file apt-cdrom seq 0x17502251869115172482 key 70:aa73:0
>[2018/07/11 20:03:14.716648, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:5363(create_file_unixpath)
>  create_file_unixpath: info=1
>[2018/07/11 20:03:14.716666, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/open.c:5642(create_file_default)
>  create_file: info=1
>[2018/07/11 20:03:14.716685, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_create.c:1281(smbd_smb2_create_after_exec)
>  smbd_smb2_create_send: response construction phase
>[2018/07/11 20:03:14.716703,  8, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:667(dos_mode)
>  dos_mode: apt-cdrom
>[2018/07/11 20:03:14.716723,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print)
>  dos_mode_debug_print: dos_mode_from_sbuf returning (0x20): "a"
>[2018/07/11 20:03:14.716742,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dosmode.c:70(dos_mode_debug_print)
>  dos_mode_debug_print: dos_mode returning (0x20): "a"
>[2018/07/11 20:03:14.716761, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_create.c:1507(smbd_smb2_create_finish)
>  smbd_smb2_create_finish: apt-cdrom - fnum 4209999639
>[2018/07/11 20:03:14.716782, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:3062(smbd_smb2_request_done_ex)
>  smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[88] dyn[yes:0] at ../source3/smbd/smb2_create.c:367
>[2018/07/11 20:03:14.716803, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:936(smb2_set_operation_credit)
>  smb2_set_operation_credit: smb2_set_operation_credit: requested 7681, charge 1, granted 1, current possible/max 1/512, total granted/max/low/range 512/8192/244/512
>[2018/07/11 20:03:14.716915, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:3934(smbd_smb2_io_handler)
>  smbd_smb2_request idx[1] of 5 vectors
>[2018/07/11 20:03:14.716939, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:678(smb2_validate_sequence_number)
>  smb2_validate_sequence_number: smb2_validate_sequence_number: clearing id 244 (position 244) from bitmap
>[2018/07/11 20:03:14.716959, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:2327(smbd_smb2_request_dispatch)
>  smbd_smb2_request_dispatch: opcode[SMB2_OP_CLOSE] mid = 244
>[2018/07/11 20:03:14.716978,  4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/uid.c:384(change_to_user)
>  Skipping user change - already user
>[2018/07/11 20:03:14.716999, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_close.c:230(smbd_smb2_close)
>  smbd_smb2_close: apt-cdrom - fnum 4209999639
>[2018/07/11 20:03:14.717020,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:130(dbwrap_lock_order_lock)
>  dbwrap_lock_order_lock: check lock order 1 for /var/run/samba/locking.tdb
>[2018/07/11 20:03:14.717039, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:116(debug_lock_order)
>  lock order:  1:/var/run/samba/locking.tdb 2:<none> 3:<none>
>[2018/07/11 20:03:14.717060, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key)
>  Locking key 700000000000000073AA
>[2018/07/11 20:03:14.717080, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:145(db_tdb_fetch_locked_internal)
>  Allocated locked data 0x0x564278575130
>[2018/07/11 20:03:14.717101, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:285(share_mode_memcache_fetch)
>  fetched entry for file apt-cdrom seq 0x17502251869115172482 key 70:aa73:0
>[2018/07/11 20:03:14.717121, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/locking.c:1226(find_delete_on_close_token)
>  find_delete_on_close_token: name_hash = 0x421ed6b5
>[2018/07/11 20:03:14.717145, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/locking.c:1226(find_delete_on_close_token)
>  find_delete_on_close_token: name_hash = 0x421ed6b5
>[2018/07/11 20:03:14.717164, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/locking.c:1232(find_delete_on_close_token)
>  find__delete_on_close_token: dt->name_hash = 0x421ed6b5
>[2018/07/11 20:03:14.717183,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/close.c:373(close_remove_share_mode)
>  close_remove_share_mode: file apt-cdrom. Delete on close was set - deleting file.
>[2018/07/11 20:03:14.717202, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/locking.c:1226(find_delete_on_close_token)
>  find_delete_on_close_token: name_hash = 0x421ed6b5
>[2018/07/11 20:03:14.717220, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/locking.c:1232(find_delete_on_close_token)
>  find__delete_on_close_token: dt->name_hash = 0x421ed6b5
>[2018/07/11 20:03:14.717244, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:47(recycle_repository)
>  recycle: repository = .recycle
>[2018/07/11 20:03:14.717269, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:136(recycle_maxsize)
>  recycle: maxsize = 0
>[2018/07/11 20:03:14.717289, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:148(recycle_minsize)
>  recycle: minsize = 0
>[2018/07/11 20:03:14.717308, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:547(recycle_unlink)
>  recycle: fname = apt-cdrom
>[2018/07/11 20:03:14.717326, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:549(recycle_unlink)
>  recycle: fpath = /
>[2018/07/11 20:03:14.717344, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:551(recycle_unlink)
>  recycle: base = apt-cdrom
>[2018/07/11 20:03:14.717363, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:102(recycle_exclude)
>  recycle: exclude =  ...
>[2018/07/11 20:03:14.717382, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:113(recycle_exclude_dir)
>  recycle: exclude_dir =  ...
>[2018/07/11 20:03:14.717400, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:58(recycle_keep_dir_tree)
>  recycle_bin: keeptree = False
>[2018/07/11 20:03:14.717422, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:576(recycle_unlink)
>  recycle: Directory already exists
>[2018/07/11 20:03:14.717441, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:605(recycle_unlink)
>  recycle: recycled file name: .recycle/apt-cdrom
>[2018/07/11 20:03:14.717473, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:636(recycle_unlink)
>  recycle: Moving apt-cdrom to .recycle/apt-cdrom
>[2018/07/11 20:03:14.717540, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:80(recycle_touch)
>  recycle: touch = False
>[2018/07/11 20:03:14.717571, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=recycle] ../source3/modules/vfs_recycle.c:91(recycle_touch_mtime)
>  recycle: touch_mtime = False
>[2018/07/11 20:03:14.717596, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:368(unparse_share_modes)
>  unparse_share_modes:
>[2018/07/11 20:03:14.717615,  1, pid=6945, effective(1000, 1000), real(1000, 0), class=rpc_parse] ../librpc/ndr/ndr.c:422(ndr_print_debug)
>       d: struct share_mode_data
>          sequence_number          : 0xf2e47d581406c682 (-944492204594379134)
>          servicepath              : *
>              servicepath              : '/storage'
>          base_name                : *
>              base_name                : 'apt-cdrom'
>          stream_name              : NULL
>          num_share_modes          : 0x00000000 (0)
>          share_modes: ARRAY(0)
>          num_leases               : 0x00000000 (0)
>          leases: ARRAY(0)
>          num_delete_tokens        : 0x00000000 (0)
>          delete_tokens: ARRAY(0)
>          old_write_time           : Wed Jul 11 19:46:34 2018 UTC.432775009
>          changed_write_time       : Thu Jan  1 00:00:00 1970 UTC.0
>          fresh                    : 0x00 (0)
>          modified                 : 0x01 (1)
>          record                   : *
>          id: struct file_id
>              devid                    : 0x0000000000000070 (112)
>              inode                    : 0x000000000000aa73 (43635)
>              extid                    : 0x0000000000000000 (0)
>[2018/07/11 20:03:14.717799, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:157(share_mode_memcache_delete)
>  deleting entry for file apt-cdrom seq 0x17502251869115172482 key 70:aa73:0
>[2018/07/11 20:03:14.717829, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:380(unparse_share_modes)
>  No used share mode found
>[2018/07/11 20:03:14.717854,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_lock_order_unlock)
>  dbwrap_lock_order_unlock: release lock order 1 for /var/run/samba/locking.tdb
>[2018/07/11 20:03:14.717876, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key)
>  Unlocking key 700000000000000073AA
>[2018/07/11 20:03:14.717896, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/notify_msg.c:218(notify_trigger)
>  notify_trigger called action=0x2, filter=0x1, dir=/storage, name=apt-cdrom
>[2018/07/11 20:03:14.717938,  4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/sec_ctx.c:216(push_sec_ctx)
>  push_sec_ctx(1000, 1000) : sec_ctx_stack_ndx = 1
>[2018/07/11 20:03:14.717963,  4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/uid.c:491(push_conn_ctx)
>  push_conn_ctx(1220382092) : conn_ctx_stack_ndx = 0
>[2018/07/11 20:03:14.717983,  4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
>  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
>[2018/07/11 20:03:14.718002,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../libcli/security/security_token.c:53(security_token_debug)
>  Security token: (NULL)
>[2018/07/11 20:03:14.718020,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/auth/token_util.c:810(debug_unix_user_token)
>  UNIX token of user 0
>  Primary group is 0 and contains 0 supplementary groups
>[2018/07/11 20:03:14.718067, 10, pid=6945, effective(0, 0), real(0, 0)] ../source3/lib/messages_dgm.c:1430(messaging_dgm_send)
>  messaging_dgm_send: Sending message to 6848
>[2018/07/11 20:03:14.718115,  4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/sec_ctx.c:438(pop_sec_ctx)
>  pop_sec_ctx (1000, 1000) - sec_ctx_stack_ndx = 0
>[2018/07/11 20:03:14.718148,  2, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/close.c:805(close_normal_file)
>  ubuntu closed file apt-cdrom (numopen=1) NT_STATUS_OK
>[2018/07/11 20:03:14.718177,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:130(dbwrap_lock_order_lock)
>  dbwrap_lock_order_lock: check lock order 1 for /var/run/samba/smbXsrv_open_global.tdb
>[2018/07/11 20:03:14.718206, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:116(debug_lock_order)
>  lock order:  1:/var/run/samba/smbXsrv_open_global.tdb 2:<none> 3:<none>
>[2018/07/11 20:03:14.718235, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key)
>  Locking key C7B9C9E0
>[2018/07/11 20:03:14.718276, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:145(db_tdb_fetch_locked_internal)
>  Allocated locked data 0x0x564278574060
>[2018/07/11 20:03:14.718308, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key)
>  Unlocking key C7B9C9E0
>[2018/07/11 20:03:14.718328,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_lock_order_unlock)
>  dbwrap_lock_order_unlock: release lock order 1 for /var/run/samba/smbXsrv_open_global.tdb
>[2018/07/11 20:03:14.718348,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:563(file_free)
>  freed files structure 4209999639 (1 used)
>[2018/07/11 20:03:14.718370, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:3062(smbd_smb2_request_done_ex)
>  smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[60] dyn[no:0] at ../source3/smbd/smb2_close.c:147
>[2018/07/11 20:03:14.718391, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:936(smb2_set_operation_credit)
>  smb2_set_operation_credit: smb2_set_operation_credit: requested 7681, charge 1, granted 1, current possible/max 1/512, total granted/max/low/range 512/8192/245/512
>[2018/07/11 20:03:14.718489, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:3934(smbd_smb2_io_handler)
>  smbd_smb2_request idx[1] of 5 vectors
>[2018/07/11 20:03:14.718517, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:678(smb2_validate_sequence_number)
>  smb2_validate_sequence_number: smb2_validate_sequence_number: clearing id 245 (position 245) from bitmap
>[2018/07/11 20:03:14.718537, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:2327(smbd_smb2_request_dispatch)
>  smbd_smb2_request_dispatch: opcode[SMB2_OP_CLOSE] mid = 245
>[2018/07/11 20:03:14.718556,  4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/uid.c:384(change_to_user)
>  Skipping user change - already user
>[2018/07/11 20:03:14.718580, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_close.c:230(smbd_smb2_close)
>  smbd_smb2_close: . - fnum 3308792266
>[2018/07/11 20:03:14.718611,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:130(dbwrap_lock_order_lock)
>  dbwrap_lock_order_lock: check lock order 1 for /var/run/samba/locking.tdb
>[2018/07/11 20:03:14.718644, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:116(debug_lock_order)
>  lock order:  1:/var/run/samba/locking.tdb 2:<none> 3:<none>
>[2018/07/11 20:03:14.718682, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key)
>  Locking key 7000000000000000A3A7
>[2018/07/11 20:03:14.718728, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:145(db_tdb_fetch_locked_internal)
>  Allocated locked data 0x0x564278565610
>[2018/07/11 20:03:14.718793, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:285(share_mode_memcache_fetch)
>  fetched entry for file . seq 0x14279333256817674529 key 70:a7a3:0
>[2018/07/11 20:03:14.718850, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/locking.c:1226(find_delete_on_close_token)
>  find_delete_on_close_token: name_hash = 0x83de38f3
>[2018/07/11 20:03:14.718905, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:368(unparse_share_modes)
>  unparse_share_modes:
>[2018/07/11 20:03:14.718951,  1, pid=6945, effective(1000, 1000), real(1000, 0), class=rpc_parse] ../librpc/ndr/ndr.c:422(ndr_print_debug)
>       d: struct share_mode_data
>          sequence_number          : 0xc62a61f1220a0921 (-4167410816891877087)
>          servicepath              : *
>              servicepath              : '/storage'
>          base_name                : *
>              base_name                : '.'
>          stream_name              : NULL
>          num_share_modes          : 0x00000000 (0)
>          share_modes: ARRAY(0)
>          num_leases               : 0x00000000 (0)
>          leases: ARRAY(0)
>          num_delete_tokens        : 0x00000000 (0)
>          delete_tokens: ARRAY(0)
>          old_write_time           : Thu Jan  1 00:00:00 1970 UTC.0
>          changed_write_time       : Thu Jan  1 00:00:00 1970 UTC.0
>          fresh                    : 0x00 (0)
>          modified                 : 0x01 (1)
>          record                   : *
>          id: struct file_id
>              devid                    : 0x0000000000000070 (112)
>              inode                    : 0x000000000000a7a3 (42915)
>              extid                    : 0x0000000000000000 (0)
>[2018/07/11 20:03:14.719446, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:157(share_mode_memcache_delete)
>  deleting entry for file . seq 0x14279333256817674529 key 70:a7a3:0
>[2018/07/11 20:03:14.719481, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=locking] ../source3/locking/share_mode_lock.c:380(unparse_share_modes)
>  No used share mode found
>[2018/07/11 20:03:14.719508,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_lock_order_unlock)
>  dbwrap_lock_order_unlock: release lock order 1 for /var/run/samba/locking.tdb
>[2018/07/11 20:03:14.719533, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key)
>  Unlocking key 7000000000000000A3A7
>[2018/07/11 20:03:14.719555,  4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/dir.c:233(dptr_close_internal)
>  closing dptr key 0
>[2018/07/11 20:03:14.719606,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:130(dbwrap_lock_order_lock)
>  dbwrap_lock_order_lock: check lock order 1 for /var/run/samba/smbXsrv_open_global.tdb
>[2018/07/11 20:03:14.719631, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:116(debug_lock_order)
>  lock order:  1:/var/run/samba/smbXsrv_open_global.tdb 2:<none> 3:<none>
>[2018/07/11 20:03:14.719651, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key)
>  Locking key 0886D56E
>[2018/07/11 20:03:14.719671, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:145(db_tdb_fetch_locked_internal)
>  Allocated locked data 0x0x564278574060
>[2018/07/11 20:03:14.719696, 10, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap_tdb.c:61(db_tdb_log_key)
>  Unlocking key 0886D56E
>[2018/07/11 20:03:14.719715,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../lib/dbwrap/dbwrap.c:159(dbwrap_lock_order_unlock)
>  dbwrap_lock_order_unlock: release lock order 1 for /var/run/samba/smbXsrv_open_global.tdb
>[2018/07/11 20:03:14.719736,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/files.c:563(file_free)
>  freed files structure 3308792266 (0 used)
>[2018/07/11 20:03:14.719761, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:3062(smbd_smb2_request_done_ex)
>  smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[60] dyn[no:0] at ../source3/smbd/smb2_close.c:147
>[2018/07/11 20:03:14.719785, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:936(smb2_set_operation_credit)
>  smb2_set_operation_credit: smb2_set_operation_credit: requested 7681, charge 1, granted 1, current possible/max 1/512, total granted/max/low/range 512/8192/246/512
>[2018/07/11 20:03:15.321807, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:3934(smbd_smb2_io_handler)
>  smbd_smb2_request idx[1] of 5 vectors
>[2018/07/11 20:03:15.321983, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:678(smb2_validate_sequence_number)
>  smb2_validate_sequence_number: smb2_validate_sequence_number: clearing id 246 (position 246) from bitmap
>[2018/07/11 20:03:15.322061, 10, pid=6945, effective(1000, 1000), real(1000, 0), class=smb2] ../source3/smbd/smb2_server.c:2327(smbd_smb2_request_dispatch)
>  smbd_smb2_request_dispatch: opcode[SMB2_OP_KEEPALIVE] mid = 246
>[2018/07/11 20:03:15.322133,  4, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
>  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
>[2018/07/11 20:03:15.322198,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../libcli/security/security_token.c:53(security_token_debug)
>  Security token: (NULL)
>[2018/07/11 20:03:15.322261,  5, pid=6945, effective(1000, 1000), real(1000, 0)] ../source3/auth/token_util.c:810(debug_unix_user_token)
>  UNIX token of user 0
>  Primary group is 0 and contains 0 supplementary groups
>[2018/07/11 20:03:15.322384,  5, pid=6945, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:425(smbd_change_to_root_user)
>  change_to_root_user: now uid=(0,0) gid=(0,0)
>[2018/07/11 20:03:15.322465, 10, pid=6945, effective(0, 0), real(0, 0), class=smb2] ../source3/smbd/smb2_server.c:3062(smbd_smb2_request_done_ex)
>  smbd_smb2_request_done_ex: idx[1] status[NT_STATUS_OK] body[4] dyn[no:0] at ../source3/smbd/smb2_keepalive.c:49
>[2018/07/11 20:03:15.322533, 10, pid=6945, effective(0, 0), real(0, 0), class=smb2_credits] ../source3/smbd/smb2_server.c:936(smb2_set_operation_credit)
>  smb2_set_operation_credit: smb2_set_operation_credit: requested 7681, charge 1, granted 1, current possible/max 1/512, total granted/max/low/range 512/8192/247/512
>[2018/07/11 20:03:15.883570, 10, pid=6945, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:42(smbd_idle_event_handler)
>  smbd_idle_event_handler: idle_evt(deadtime) (nil) called
>[2018/07/11 20:03:15.883828, 10, pid=6945, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:53(smbd_idle_event_handler)
>  smbd_idle_event_handler: idle_evt(deadtime) (nil) rescheduled
>[2018/07/11 20:03:15.883935, 10, pid=6945, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:42(smbd_idle_event_handler)
>  smbd_idle_event_handler: idle_evt(housekeeping) (nil) called
>[2018/07/11 20:03:15.884017,  5, pid=6945, effective(0, 0), real(0, 0)] ../source3/smbd/process.c:2898(housekeeping_fn)
>  housekeeping
>[2018/07/11 20:03:15.884094,  4, pid=6945, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal)
>  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
>[2018/07/11 20:03:15.884167,  5, pid=6945, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug)
>  Security token: (NULL)
>[2018/07/11 20:03:15.884238,  5, pid=6945, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:810(debug_unix_user_token)
>  UNIX token of user 0
>  Primary group is 0 and contains 0 supplementary groups
>[2018/07/11 20:03:15.884361,  5, pid=6945, effective(0, 0), real(0, 0)] ../source3/smbd/uid.c:425(smbd_change_to_root_user)
>  change_to_root_user: now uid=(0,0) gid=(0,0)
>[2018/07/11 20:03:15.884458, 10, pid=6945, effective(0, 0), real(0, 0)] ../source3/lib/util_event.c:53(smbd_idle_event_handler)
>  smbd_idle_event_handler: idle_evt(housekeeping) (nil) rescheduled

Actions: View

Attachments on bug 13524: 14320