sid : * sid MyUser Name : S-1-5-21-434767867-3756878010-1975691145-513 [2016/11/28 17:50:45.238261, 1, pid=26853, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:439(ndr_print_function_debug) wbint_LookupSid: struct wbint_LookupSid out: struct wbint_LookupSid type : * type : SID_NAME_DOM_GRP (2) domain : * domain : * domain : 'MyDOMAIN' name : * name : * name : 'Domain-User result : NT_STATUS_OK [2016/11/28 17:50:45.238312, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/wb_sids2xids.c:106(wb_sids2xids_send) SID 0: S-1-5-21-434767867-3756878010-1975691145-513 [2016/11/28 17:50:45.238329, 10, pid=26853, effective(0, 0), real(0, 0)] ../source3/lib/idmap_cache.c:56(idmap_cache_find_sid2unixid) Parsing value for key [IDMAP/SID2XID/S-1-5-21-434767867-3756878010-1975691145-513]: value=[10513:B] [2016/11/28 17:50:45.238338, 10, pid=26853, effective(0, 0), real(0, 0)] ../source3/lib/idmap_cache.c:75(idmap_cache_find_sid2unixid) Parsing value for key [IDMAP/SID2XID/S-1-5-21-434767867-3756878010-1975691145-513]: id=[10513], endptr=[:B] [2016/11/28 17:50:45.238355, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:542(refresh_sequence_number) refresh_sequence_number: MyDOMAIN time ok [2016/11/28 17:50:45.238364, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:587(refresh_sequence_number) refresh_sequence_number: MyDOMAIN seq number is now 3020058 [2016/11/28 17:50:45.238378, 5, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:1189(resolve_username_to_alias) resolve_username_to_alias: backend query returned NT_STATUS_NOT_IMPLEMENTED [2016/11/28 17:50:45.238397, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:793(wb_request_done) wb_request_done[26867:GETPWUID]: NT_STATUS_OK [2016/11/28 17:50:45.238419, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:861(winbind_client_response_written) winbind_client_response_written[26867:GETPWUID]: delivered response to client [2016/11/28 17:50:45.238491, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:731(process_request) process_request: Handling async request 26867:GETPWUID [2016/11/28 17:50:45.238501, 3, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_getpwuid.c:47(winbindd_getpwuid_send) getpwuid 11104 [2016/11/28 17:50:45.238516, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/wb_uid2sid.c:52(wb_uid2sid_send) idmap_cache_find_uid2sid found 11104 [2016/11/28 17:50:45.238530, 1, pid=26853, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:439(ndr_print_function_debug) wbint_QueryUser: struct wbint_QueryUser in: struct wbint_QueryUser sid : * sid : S-1-5-21-434767867-3756878010-1975691145-1104 [2016/11/28 17:50:45.238569, 1, pid=26853, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:439(ndr_print_function_debug) wbint_QueryUser: struct wbint_QueryUser out: struct wbint_QueryUser info : * info: struct wbint_userinfo acct_name : * acct_name : 'myuser.name' full_name : * full_name : 'MyUser Name Long' homedir : * homedir : '/mnt' shell : * shell : '/bin/sh' primary_gid : 0x00000000ffffffff (4294967295) user_sid : S-1-5-21-434767867-3756878010-1975691145-1104 group_sid : S-1-5-21-434767867-3756878010-1975691145-513 result : NT_STATUS_OK [2016/11/28 17:50:45.238649, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/wb_sids2xids.c:106(wb_sids2xids_send) SID 0: S-1-5-21-434767867-3756878010-1975691145-1104 [2016/11/28 17:50:45.238666, 10, pid=26853, effective(0, 0), real(0, 0)] ../source3/lib/idmap_cache.c:56(idmap_cache_find_sid2unixid) Parsing value for key [IDMAP/SID2XID/S-1-5-21-434767867-3756878010-1975691145-1104]: value=[11104:B] [2016/11/28 17:50:45.238675, 10, pid=26853, effective(0, 0), real(0, 0)] ../source3/lib/idmap_cache.c:75(idmap_cache_find_sid2unixid) Parsing value for key [IDMAP/SID2XID/S-1-5-21-434767867-3756878010-1975691145-1104]: id=[11104], endptr=[:B] [2016/11/28 17:50:45.238687, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_util.c:1035(find_lookup_domain_from_sid) find_lookup_domain_from_sid(S-1-5-21-434767867-3756878010-1975691145-513) [2016/11/28 17:50:45.238698, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_util.c:1045(find_lookup_domain_from_sid) calling find_our_domain [2016/11/28 17:50:45.238708, 1, pid=26853, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:439(ndr_print_function_debug) wbint_LookupSid: struct wbint_LookupSid in: struct wbint_LookupSid sid : * sid : S-1-5-21-434767867-3756878010-1975691145-513 [2016/11/28 17:50:45.238742, 1, pid=26853, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:439(ndr_print_function_debug) wbint_LookupSid: struct wbint_LookupSid out: struct wbint_LookupSid type : * type : SID_NAME_DOM_GRP (2) domain : * domain : * domain : 'MyDOMAIN' name : * name : * name : 'Domain-User result : NT_STATUS_OK [2016/11/28 17:50:45.238790, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/wb_sids2xids.c:106(wb_sids2xids_send) SID 0: S-1-5-21-434767867-3756878010-1975691145-513 [2016/11/28 17:50:45.238806, 10, pid=26853, effective(0, 0), real(0, 0)] ../source3/lib/idmap_cache.c:56(idmap_cache_find_sid2unixid) Parsing value for key [IDMAP/SID2XID/S-1-5-21-434767867-3756878010-1975691145-513]: value=[10513:B] [2016/11/28 17:50:45.238814, 10, pid=26853, effective(0, 0), real(0, 0)] ../source3/lib/idmap_cache.c:75(idmap_cache_find_sid2unixid) Parsing value for key [IDMAP/SID2XID/S-1-5-21-434767867-3756878010-1975691145-513]: id=[10513], endptr=[:B] [2016/11/28 17:50:45.238829, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:542(refresh_sequence_number) refresh_sequence_number: MyDOMAIN time ok [2016/11/28 17:50:45.238838, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:587(refresh_sequence_number) refresh_sequence_number: MyDOMAIN seq number is now 3020058 [2016/11/28 17:50:45.238850, 5, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:1189(resolve_username_to_alias) resolve_username_to_alias: backend query returned NT_STATUS_NOT_IMPLEMENTED [2016/11/28 17:50:45.238866, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:793(wb_request_done) wb_request_done[26867:GETPWUID]: NT_STATUS_OK [2016/11/28 17:50:45.238886, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:861(winbind_client_response_written) winbind_client_response_written[26867:GETPWUID]: delivered response to client [2016/11/28 17:50:45.239213, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:731(process_request) process_request: Handling async request 26867:GETPWUID [2016/11/28 17:50:45.239224, 3, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_getpwuid.c:47(winbindd_getpwuid_send) getpwuid 11104 [2016/11/28 17:50:45.239239, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/wb_uid2sid.c:52(wb_uid2sid_send) idmap_cache_find_uid2sid found 11104 [2016/11/28 17:50:45.239251, 1, pid=26853, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:439(ndr_print_function_debug) wbint_QueryUser: struct wbint_QueryUser in: struct wbint_QueryUser sid : * sid : S-1-5-21-434767867-3756878010-1975691145-1104 [2016/11/28 17:50:45.239289, 1, pid=26853, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:439(ndr_print_function_debug) wbint_QueryUser: struct wbint_QueryUser out: struct wbint_QueryUser info : * info: struct wbint_userinfo acct_name : * acct_name : 'myuser.name' full_name : * full_name : 'MyUser Name Long' homedir : * homedir : '/mnt' shell : * shell : '/bin/sh' primary_gid : 0x00000000ffffffff (4294967295) user_sid : S-1-5-21-434767867-3756878010-1975691145-1104 group_sid : S-1-5-21-434767867-3756878010-1975691145-513 result : NT_STATUS_OK [2016/11/28 17:50:45.239364, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/wb_sids2xids.c:106(wb_sids2xids_send) SID 0: S-1-5-21-434767867-3756878010-1975691145-1104 [2016/11/28 17:50:45.239381, 10, pid=26853, effective(0, 0), real(0, 0)] ../source3/lib/idmap_cache.c:56(idmap_cache_find_sid2unixid) Parsing value for key [IDMAP/SID2XID/S-1-5-21-434767867-3756878010-1975691145-1104]: value=[11104:B] [2016/11/28 17:50:45.239390, 10, pid=26853, effective(0, 0), real(0, 0)] ../source3/lib/idmap_cache.c:75(idmap_cache_find_sid2unixid) Parsing value for key [IDMAP/SID2XID/S-1-5-21-434767867-3756878010-1975691145-1104]: id=[11104], endptr=[:B] [2016/11/28 17:50:45.239401, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_util.c:1035(find_lookup_domain_from_sid) find_lookup_domain_from_sid(S-1-5-21-434767867-3756878010-1975691145-513) [2016/11/28 17:50:45.239412, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_util.c:1045(find_lookup_domain_from_sid) calling find_our_domain [2016/11/28 17:50:45.239422, 1, pid=26853, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:439(ndr_print_function_debug) wbint_LookupSid: struct wbint_LookupSid in: struct wbint_LookupSid sid : * sid : S-1-5-21-434767867-3756878010-1975691145-513 [2016/11/28 17:50:45.239455, 1, pid=26853, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:439(ndr_print_function_debug) wbint_LookupSid: struct wbint_LookupSid out: struct wbint_LookupSid type : * type : SID_NAME_DOM_GRP (2) domain : * domain : * domain : 'MyDOMAIN' name : * name : * name : 'Domain-User result : NT_STATUS_OK [2016/11/28 17:50:45.239506, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/wb_sids2xids.c:106(wb_sids2xids_send) SID 0: S-1-5-21-434767867-3756878010-1975691145-513 [2016/11/28 17:50:45.239523, 10, pid=26853, effective(0, 0), real(0, 0)] ../source3/lib/idmap_cache.c:56(idmap_cache_find_sid2unixid) Parsing value for key [IDMAP/SID2XID/S-1-5-21-434767867-3756878010-1975691145-513]: value=[10513:B] [2016/11/28 17:50:45.239531, 10, pid=26853, effective(0, 0), real(0, 0)] ../source3/lib/idmap_cache.c:75(idmap_cache_find_sid2unixid) Parsing value for key [IDMAP/SID2XID/S-1-5-21-434767867-3756878010-1975691145-513]: id=[10513], endptr=[:B] [2016/11/28 17:50:45.239546, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:542(refresh_sequence_number) refresh_sequence_number: MyDOMAIN time ok [2016/11/28 17:50:45.239555, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:587(refresh_sequence_number) refresh_sequence_number: MyDOMAIN seq number is now 3020058 [2016/11/28 17:50:45.239567, 5, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:1189(resolve_username_to_alias) resolve_username_to_alias: backend query returned NT_STATUS_NOT_IMPLEMENTED [2016/11/28 17:50:45.239582, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:793(wb_request_done) wb_request_done[26867:GETPWUID]: NT_STATUS_OK [2016/11/28 17:50:45.239601, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:861(winbind_client_response_written) winbind_client_response_written[26867:GETPWUID]: delivered response to client [2016/11/28 17:50:45.239667, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:731(process_request) process_request: Handling async request 26867:GETPWUID [2016/11/28 17:50:45.239677, 3, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_getpwuid.c:47(winbindd_getpwuid_send) getpwuid 11104 [2016/11/28 17:50:45.239692, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/wb_uid2sid.c:52(wb_uid2sid_send) idmap_cache_find_uid2sid found 11104 [2016/11/28 17:50:45.239705, 1, pid=26853, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:439(ndr_print_function_debug) wbint_QueryUser: struct wbint_QueryUser in: struct wbint_QueryUser sid : * sid : S-1-5-21-434767867-3756878010-1975691145-1104 [2016/11/28 17:50:45.239742, 1, pid=26853, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:439(ndr_print_function_debug) wbint_QueryUser: struct wbint_QueryUser out: struct wbint_QueryUser info : * info: struct wbint_userinfo acct_name : * acct_name : 'myuser.name' full_name : * full_name : 'MyUser Name Long' homedir : * homedir : '/mnt' shell : * shell : '/bin/sh' primary_gid : 0x00000000ffffffff (4294967295) user_sid : S-1-5-21-434767867-3756878010-1975691145-1104 group_sid : S-1-5-21-434767867-3756878010-1975691145-513 result : NT_STATUS_OK [2016/11/28 17:50:45.239816, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/wb_sids2xids.c:106(wb_sids2xids_send) SID 0: S-1-5-21-434767867-3756878010-1975691145-1104 [2016/11/28 17:50:45.239837, 10, pid=26853, effective(0, 0), real(0, 0)] ../source3/lib/idmap_cache.c:56(idmap_cache_find_sid2unixid) Parsing value for key [IDMAP/SID2XID/S-1-5-21-434767867-3756878010-1975691145-1104]: value=[11104:B] [2016/11/28 17:50:45.239846, 10, pid=26853, effective(0, 0), real(0, 0)] ../source3/lib/idmap_cache.c:75(idmap_cache_find_sid2unixid) Parsing value for key [IDMAP/SID2XID/S-1-5-21-434767867-3756878010-1975691145-1104]: id=[11104], endptr=[:B] [2016/11/28 17:50:45.239857, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_util.c:1035(find_lookup_domain_from_sid) find_lookup_domain_from_sid(S-1-5-21-434767867-3756878010-1975691145-513) [2016/11/28 17:50:45.239869, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_util.c:1045(find_lookup_domain_from_sid) calling find_our_domain [2016/11/28 17:50:45.239878, 1, pid=26853, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:439(ndr_print_function_debug) wbint_LookupSid: struct wbint_LookupSid in: struct wbint_LookupSid sid : * sid : S-1-5-21-434767867-3756878010-1975691145-513 [2016/11/28 17:50:45.239912, 1, pid=26853, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:439(ndr_print_function_debug) wbint_LookupSid: struct wbint_LookupSid out: struct wbint_LookupSid type : * type : SID_NAME_DOM_GRP (2) domain : * domain : * domain : 'MyDOMAIN' name : * name : * name : 'Domain-User result : NT_STATUS_OK [2016/11/28 17:50:45.239960, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/wb_sids2xids.c:106(wb_sids2xids_send) SID 0: S-1-5-21-434767867-3756878010-1975691145-513 [2016/11/28 17:50:45.239976, 10, pid=26853, effective(0, 0), real(0, 0)] ../source3/lib/idmap_cache.c:56(idmap_cache_find_sid2unixid) Parsing value for key [IDMAP/SID2XID/S-1-5-21-434767867-3756878010-1975691145-513]: value=[10513:B] [2016/11/28 17:50:45.239985, 10, pid=26853, effective(0, 0), real(0, 0)] ../source3/lib/idmap_cache.c:75(idmap_cache_find_sid2unixid) Parsing value for key [IDMAP/SID2XID/S-1-5-21-434767867-3756878010-1975691145-513]: id=[10513], endptr=[:B] [2016/11/28 17:50:45.239999, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:542(refresh_sequence_number) refresh_sequence_number: MyDOMAIN time ok [2016/11/28 17:50:45.240008, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:587(refresh_sequence_number) refresh_sequence_number: MyDOMAIN seq number is now 3020058 [2016/11/28 17:50:45.240020, 5, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:1189(resolve_username_to_alias) resolve_username_to_alias: backend query returned NT_STATUS_NOT_IMPLEMENTED [2016/11/28 17:50:45.240035, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:793(wb_request_done) wb_request_done[26867:GETPWUID]: NT_STATUS_OK [2016/11/28 17:50:45.240056, 10, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:861(winbind_client_response_written) winbind_client_response_written[26867:GETPWUID]: delivered response to client [2016/11/28 17:50:45.240713, 10, pid=26867, effective(0, 0), real(0, 0)] ../source3/lib/messages_dgm.c:284(messaging_dgm_send) messaging_dgm_send: Sending message to 26852 [2016/11/28 17:50:45.240772, 4, pid=26867, effective(11104, 10513), real(0, 0)] ../source3/smbd/sec_ctx.c:439(pop_sec_ctx) pop_sec_ctx (11104, 10513) - sec_ctx_stack_ndx = 0 [2016/11/28 17:50:45.240786, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:3160(fruit_streaminfo) fruit_streaminfo called for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar [2016/11/28 17:50:45.240805, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:1179(ad_get) ad_get(meta) called for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar [2016/11/28 17:50:45.240815, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:759(ad_header_read_meta) reading meta xattr for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar [2016/11/28 17:50:45.240835, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:811(ad_header_read_meta) reading meta xattr for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar, rc: -1 [2016/11/28 17:50:45.240845, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:1189(ad_get) error reading AppleDouble for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar [2016/11/28 17:50:45.240854, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:1196(ad_get) ad_get(meta) for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar returning -1 [2016/11/28 17:50:45.240863, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:1179(ad_get) ad_get(rsrc) called for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar [2016/11/28 17:50:45.240881, 2, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:887(ad_header_read_rsrc) open AppleDouble: Starface/starface-backup/MyDOMAIN1/._backup-MyDOMAIN1-1480351803929.sar, No such file or directory [2016/11/28 17:50:45.240899, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:1189(ad_get) error reading AppleDouble for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar [2016/11/28 17:50:45.240907, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:1196(ad_get) ad_get(rsrc) for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar returning -1 [2016/11/28 17:50:45.240919, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:2990(fruit_lstat) fruit_lstat called for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar [2016/11/28 17:50:45.240935, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:1179(ad_get) ad_get(meta) called for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar [2016/11/28 17:50:45.240944, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:759(ad_header_read_meta) reading meta xattr for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar [2016/11/28 17:50:45.240960, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:811(ad_header_read_meta) reading meta xattr for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar, rc: -1 [2016/11/28 17:50:45.240969, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:1189(ad_get) error reading AppleDouble for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar [2016/11/28 17:50:45.240978, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:1196(ad_get) ad_get(meta) for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar returning -1 [2016/11/28 17:50:45.240989, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:2990(fruit_lstat) fruit_lstat called for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar [2016/11/28 17:50:45.241004, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:1179(ad_get) ad_get(meta) called for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar [2016/11/28 17:50:45.241026, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:759(ad_header_read_meta) reading meta xattr for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar [2016/11/28 17:50:45.241044, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:811(ad_header_read_meta) reading meta xattr for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar, rc: -1 [2016/11/28 17:50:45.241053, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:1189(ad_get) error reading AppleDouble for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar [2016/11/28 17:50:45.241061, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:1196(ad_get) ad_get(meta) for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar returning -1 [2016/11/28 17:50:45.241074, 10, pid=26867, effective(11104, 10513), real(0, 0)] ../source3/smbd/close.c:188(delete_all_streams) delete_all_streams found 1 streams [2016/11/28 17:50:45.241085, 10, pid=26867, effective(11104, 10513), real(0, 0), class=locking] ../source3/locking/brlock.c:2048(brl_get_locks_readonly) seqnum=0, fsp->brlock_seqnum=0 [2016/11/28 17:50:45.241096, 5, pid=26867, effective(11104, 10513), real(0, 0), class=locking] ../source3/smbd/oplock.c:86(set_file_oplock) set_file_oplock: granted oplock on file Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar, 8c:a419001:0/3440735378, tv_sec = 583c6065, tv_usec = 39dd7 [2016/11/28 17:50:45.241108, 10, pid=26867, effective(11104, 10513), real(0, 0)] ../source3/smbd/open.c:1874(grant_fsp_oplock_type) grant_fsp_oplock_type: oplock type 0x1 on file Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar [2016/11/28 17:50:45.241118, 10, pid=26867, effective(11104, 10513), real(0, 0), class=locking] ../source3/locking/share_mode_lock.c:358(unparse_share_modes) unparse_share_modes: [2016/11/28 17:50:45.241126, 1, pid=26867, effective(11104, 10513), real(0, 0)] ../librpc/ndr/ndr.c:402(ndr_print_debug) d: struct share_mode_data sequence_number : 0x3238333ebd15cd79 (3618698645145505145) servicepath : * servicepath : '/mnt/backupdir' base_name : * base_name : 'Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar' stream_name : NULL num_share_modes : 0x00000001 (1) share_modes: ARRAY(1) share_modes: struct share_mode_entry pid: struct server_id pid : 0x00000000000068f3 (26867) task_id : 0x00000000 (0) vnn : 0xffffffff (4294967295) unique_id : 0x311956e6131cc4b3 (3537954528439354547) op_mid : 0x000000000000002d (45) op_type : 0x0001 (1) lease_idx : 0xffffffff (4294967295) access_mask : 0x00000192 (402) share_access : 0x00000007 (7) private_options : 0x00000000 (0) time : Mon Nov 28 17:50:45 2016 CET.237015 id: struct file_id devid : 0x000000000000008c (140) inode : 0x000000000a419001 (172068865) extid : 0x0000000000000000 (0) share_file_id : 0x00000000cd157492 (3440735378) uid : 0x00002b60 (11104) flags : 0x0001 (1) name_hash : 0x39ff56ee (973035246) stale : 0x00 (0) lease : NULL num_leases : 0x00000000 (0) leases: ARRAY(0) num_delete_tokens : 0x00000000 (0) delete_tokens: ARRAY(0) old_write_time : Mon Nov 28 17:50:04 2016 CET.117125000 changed_write_time : Thu Jan 1 01:00:00 1970 CET.0 fresh : 0x00 (0) modified : 0x01 (1) record : * id: struct file_id devid : 0x000000000000008c (140) inode : 0x000000000a419001 (172068865) extid : 0x0000000000000000 (0) [2016/11/28 17:50:45.241311, 10, pid=26867, effective(11104, 10513), real(0, 0), class=locking] ../source3/locking/share_mode_lock.c:147(share_mode_memcache_delete) deleting entry for file Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar seq 0x3618698645145505145 key 8c:a419001:0 [2016/11/28 17:50:45.241341, 10, pid=26867, effective(11104, 10513), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key 8C000000000000000190 [2016/11/28 17:50:45.241352, 5, pid=26867, effective(11104, 10513), real(0, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 1 for /mnt/backupdir/samba4/locking.tdb [2016/11/28 17:50:45.241360, 10, pid=26867, effective(11104, 10513), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2: 3: [2016/11/28 17:50:45.241371, 10, pid=26867, effective(11104, 10513), real(0, 0), class=locking] ../source3/locking/share_mode_lock.c:161(share_mode_memcache_store) stored entry for file Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar seq 0x3618698645145505146 key 8c:a419001:0 [2016/11/28 17:50:45.241383, 10, pid=26867, effective(11104, 10513), real(0, 0)] ../source3/smbd/open.c:4792(create_file_unixpath) create_file_unixpath: info=3 [2016/11/28 17:50:45.241391, 10, pid=26867, effective(11104, 10513), real(0, 0)] ../source3/smbd/open.c:5071(create_file_default) create_file: info=3 [2016/11/28 17:50:45.241400, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:1707(fruit_check_access) fruit_check_access: Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar, am: -/WRITE, dm: -/- [2016/11/28 17:50:45.241411, 8, pid=26867, effective(11104, 10513), real(0, 0), class=locking] ../source3/lib/util.c:1157(fcntl_getlock) fcntl_getlock fd=32 offset=9223372036854775808 count=1 type=3 [2016/11/28 17:50:45.241429, 3, pid=26867, effective(11104, 10513), real(0, 0), class=locking] ../source3/lib/util.c:1181(fcntl_getlock) fcntl_getlock: fd 32 is returned info 2 pid 0 [2016/11/28 17:50:45.241438, 8, pid=26867, effective(11104, 10513), real(0, 0), class=locking] ../source3/lib/util.c:1157(fcntl_getlock) fcntl_getlock fd=32 offset=9223372036854775808 count=1 type=3 [2016/11/28 17:50:45.241449, 3, pid=26867, effective(11104, 10513), real(0, 0), class=locking] ../source3/lib/util.c:1181(fcntl_getlock) fcntl_getlock: fd 32 is returned info 2 pid 0 [2016/11/28 17:50:45.241458, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:1772(fruit_check_access) write: no, deny_write: no [2016/11/28 17:50:45.241467, 10, pid=26867, effective(11104, 10513), real(0, 0), class=locking] ../source3/locking/locking.c:268(do_lock) do_lock: lock flavour POSIX_LOCK lock type READ start=9223372036854775798 len=1 blocking_lock=false requested for fnum 21630 file Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar [2016/11/28 17:50:45.241485, 5, pid=26867, effective(11104, 10513), real(0, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 2 for /mnt/backupdir/samba4/brlock.tdb [2016/11/28 17:50:45.241493, 10, pid=26867, effective(11104, 10513), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2:/mnt/backupdir/samba4/brlock.tdb 3: [2016/11/28 17:50:45.241523, 10, pid=26867, effective(11104, 10513), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key 8C000000000000000190 [2016/11/28 17:50:45.241534, 10, pid=26867, effective(11104, 10513), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x8130450a0 [2016/11/28 17:50:45.241543, 10, pid=26867, effective(11104, 10513), real(0, 0), class=locking] ../source3/locking/brlock.c:2006(brl_get_locks) brl_get_locks_internal: 0 current locks on file_id 8c:a419001:0 [2016/11/28 17:50:45.241554, 5, pid=26867, effective(11104, 10513), real(0, 0), class=locking] ../source3/locking/posix.c:1207(set_posix_lock_posix_flavour) set_posix_lock_posix_flavour: File Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar, offset = 9223372036854775798, count = 1, type = WRITE [2016/11/28 17:50:45.241564, 10, pid=26867, effective(11104, 10513), real(0, 0), class=locking] ../source3/locking/posix.c:169(posix_lock_in_range) posix_lock_in_range: offset_out = 9223372036854775798, count_out = 1 [2016/11/28 17:50:45.241573, 8, pid=26867, effective(11104, 10513), real(0, 0), class=locking] ../source3/locking/posix.c:195(posix_fcntl_lock) posix_fcntl_lock 32 12 9223372036854775798 1 1 [2016/11/28 17:50:45.241582, 8, pid=26867, effective(11104, 10513), real(0, 0)] ../lib/util/util.c:394(fcntl_lock) fcntl_lock 32 12 9223372036854775808 1 1 [2016/11/28 17:50:45.241593, 3, pid=26867, effective(11104, 10513), real(0, 0)] ../lib/util/util.c:405(fcntl_lock) fcntl_lock: fcntl lock gave errno 9 (Bad file descriptor) [2016/11/28 17:50:45.241602, 3, pid=26867, effective(11104, 10513), real(0, 0)] ../lib/util/util.c:424(fcntl_lock) fcntl_lock: lock failed at offset 9223372036854775808 count 1 op 12 type 1 (Bad file descriptor) [2016/11/28 17:50:45.241612, 8, pid=26867, effective(11104, 10513), real(0, 0), class=locking] ../source3/locking/posix.c:227(posix_fcntl_lock) posix_fcntl_lock: Lock call failed [2016/11/28 17:50:45.241620, 5, pid=26867, effective(11104, 10513), real(0, 0), class=locking] ../source3/locking/posix.c:1221(set_posix_lock_posix_flavour) set_posix_lock_posix_flavour: Lock fail !: Type = READ: offset = 9223372036854775798, count = 1. Errno = Bad file descriptor [2016/11/28 17:50:45.241631, 10, pid=26867, effective(11104, 10513), real(0, 0), class=locking] ../source3/locking/locking.c:287(do_lock) do_lock: returning status=NT_STATUS_INVALID_HANDLE [2016/11/28 17:50:45.241639, 10, pid=26867, effective(11104, 10513), real(0, 0), class=fruit] ../source3/modules/vfs_fruit.c:3476(fruit_create_file) fruit_create_file: NT_STATUS_INVALID_HANDLE [2016/11/28 17:50:45.241648, 10, pid=26867, effective(11104, 10513), real(0, 0), class=locking] ../source3/smbd/oplock.c:237(remove_oplock) remove_oplock called for Starface/starface-backup/MyDOMAIN1/backup-MyDOMAIN1-1480351803929.sar [2016/11/28 17:50:45.241658, 5, pid=26867, effective(11104, 10513), real(0, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 1 for /mnt/backupdir/samba4/locking.tdb [2016/11/28 17:50:45.241666, 0, pid=26867, effective(11104, 10513), real(0, 0)] ../lib/dbwrap/dbwrap.c:184(dbwrap_check_lock_order) Lock order violation: Trying /mnt/backupdir/samba4/locking.tdb at 1 while /mnt/backupdir/samba4/brlock.tdb at 2 is locked [2016/11/28 17:50:45.241693, 0, pid=26867, effective(11104, 10513), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2:/mnt/backupdir/samba4/brlock.tdb 3: [2016/11/28 17:50:45.241711, 0, pid=26867, effective(11104, 10513), real(0, 0)] ../source3/lib/util.c:789(smb_panic_s3) PANIC (pid 26867): invalid lock_order [2016/11/28 17:50:45.243061, 0, pid=26867, effective(11104, 10513), real(0, 0)] ../source3/lib/util.c:900(log_stack_trace) BACKTRACE: 26 stack frames: #0 0x803847158 at /usr/local/lib/libsmbconf.so.0 #1 0x803847042 at /usr/local/lib/libsmbconf.so.0 #2 0x801687efd at /usr/local/lib/libsamba-util.so.0 #3 0x80782de3f at /usr/local/lib/samba/libdbwrap-samba4.so #4 0x801b910f2 at /usr/local/lib/samba/libsmbd-base-samba4.so #5 0x801b51d4e at /usr/local/lib/samba/libsmbd-base-samba4.so #6 0x801b01fd9 at /usr/local/lib/samba/libsmbd-base-samba4.so #7 0x813c12415 at /usr/local/lib/shared-modules/vfs/fruit.so #8 0x801ae988f at /usr/local/lib/samba/libsmbd-base-samba4.so #9 0x801aec6a8 at /usr/local/lib/samba/libsmbd-base-samba4.so #10 0x801aeae2b at /usr/local/lib/samba/libsmbd-base-samba4.so #11 0x801b19556 at /usr/local/lib/samba/libsmbd-base-samba4.so #12 0x801b1ca49 at /usr/local/lib/samba/libsmbd-base-samba4.so #13 0x801b1bf93 at /usr/local/lib/samba/libsmbd-base-samba4.so #14 0x80385be6b at /usr/local/lib/libsmbconf.so.0 #15 0x80385c661 at /usr/local/lib/libsmbconf.so.0 #16 0x804f1a8e2 <_tevent_loop_once+0x72> at /usr/local/lib/libtevent.so.0 #17 0x804f1ab1b at /usr/local/lib/libtevent.so.0 #18 0x801b1b6b1 at /usr/local/lib/samba/libsmbd-base-samba4.so #19 0x102abe1 at /usr/local/sbin/smbd #20 0x80385be6b at /usr/local/lib/libsmbconf.so.0 #21 0x80385c661 at /usr/local/lib/libsmbconf.so.0 #22 0x804f1a8e2 <_tevent_loop_once+0x72> at /usr/local/lib/libtevent.so.0 #23 0x804f1ab1b at /usr/local/lib/libtevent.so.0 #24 0x1029e9c at /usr/local/sbin/smbd #25 0x10277b1 <_start+0x1a1> at /usr/local/sbin/smbd [2016/11/28 17:50:45.243279, 4, pid=26867, effective(11104, 10513), real(0, 0)] ../source3/smbd/sec_ctx.c:217(push_sec_ctx) push_sec_ctx(11104, 10513) : sec_ctx_stack_ndx = 1 [2016/11/28 17:50:45.243292, 4, pid=26867, effective(11104, 10513), real(0, 0)] ../source3/smbd/uid.c:491(push_conn_ctx) push_conn_ctx(14920) : conn_ctx_stack_ndx = 0 [2016/11/28 17:50:45.243301, 4, pid=26867, effective(11104, 10513), real(0, 0)] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1 [2016/11/28 17:50:45.243310, 5, pid=26867, effective(11104, 10513), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2016/11/28 17:50:45.243319, 5, pid=26867, effective(11104, 10513), real(0, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2016/11/28 17:50:45.243348, 0, pid=26867, effective(0, 0), real(0, 0)] ../source3/lib/dumpcore.c:298(dump_core) unable to change to %N.core refusing to dump core [2016/11/28 17:50:45.243765, 6, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:965(winbind_client_request_read) closing socket 28, client exited [2016/11/28 17:50:45.246118, 10, pid=26849, effective(0, 0), real(0, 0)] ../source3/lib/messages_dgm.c:352(messaging_dgm_cleanup) messaging_dgm_cleanup: Cleaning up : No error: 0 [2016/11/28 17:50:45.246235, 3, pid=26849, effective(0, 0), real(0, 0)] ../source3/smbd/server.c:477(remove_child_pid) ../source3/smbd/server.c:476 Unclean shutdown of pid 26867 [2016/11/28 17:50:45.246256, 1, pid=26849, effective(0, 0), real(0, 0)] ../source3/smbd/server.c:486(remove_child_pid) Scheduled cleanup of brl and lock database after unclean shutdown [2016/11/28 17:50:45.246266, 5, pid=26849, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 2 for /mnt/backupdir/samba4/serverid.tdb [2016/11/28 17:50:45.246278, 10, pid=26849, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2:/mnt/backupdir/samba4/serverid.tdb 3: [2016/11/28 17:50:45.246300, 10, pid=26849, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key F368000000000000FFFF [2016/11/28 17:50:45.246318, 10, pid=26849, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x813043ea0 [2016/11/28 17:50:45.246339, 10, pid=26849, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key F368000000000000FFFF [2016/11/28 17:50:45.246349, 5, pid=26849, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 2 for /mnt/backupdir/samba4/serverid.tdb [2016/11/28 17:50:45.246358, 10, pid=26849, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2: 3: check lock order 2 for /mnt/backupdir/samba4/serverid.tdb [2016/11/28 17:50:45.247259, 10, pid=26868, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2:/mnt/backupdir/samba4/serverid.tdb 3: [2016/11/28 17:50:45.247276, 10, pid=26868, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key F468000000000000FFFF [2016/11/28 17:50:45.247292, 10, pid=26868, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x813043c60 [2016/11/28 17:50:45.247312, 10, pid=26868, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key F468000000000000FFFF [2016/11/28 17:50:45.247322, 5, pid=26868, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 2 for /mnt/backupdir/samba4/serverid.tdb [2016/11/28 17:50:45.247330, 10, pid=26868, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2: 3: [2016/11/28 17:50:45.247354, 5, pid=26868, effective(0, 0), real(0, 0)] ../lib/util/util_net.c:1055(print_socket_options) Socket options: SO_KEEPALIVE = 8 SO_REUSEADDR = 4 SO_BROADCAST = 0 TCP_NODELAY = 4 TCP_KEEPCNT = 0 TCP_KEEPIDLE = 0 TCP_KEEPINTVL = 0 IPTOS_LOWDELAY = 0 IPTOS_THROUGHPUT = 0 SO_REUSEPORT = 512 SO_SNDBUF = 128872 SO_RCVBUF = 128872 SO_SNDLOWAT = 2048 SO_RCVLOWAT = 1 SO_SNDTIMEO = 0 SO_RCVTIMEO = 0 [2016/11/28 17:50:45.247420, 5, pid=26868, effective(0, 0), real(0, 0)] ../lib/util/util_net.c:1055(print_socket_options) Socket options: SO_KEEPALIVE = 8 SO_REUSEADDR = 4 SO_BROADCAST = 0 TCP_NODELAY = 4 TCP_KEEPCNT = 0 TCP_KEEPIDLE = 0 TCP_KEEPINTVL = 0 IPTOS_LOWDELAY = 0 IPTOS_THROUGHPUT = 0 SO_REUSEPORT = 512 SO_SNDBUF = 128480 SO_RCVBUF = 128480 SO_SNDLOWAT = 2048 SO_RCVLOWAT = 1 SO_SNDTIMEO = 0 SO_RCVTIMEO = 0 [2016/11/28 17:50:45.247519, 3, pid=26868, effective(0, 0), real(0, 0)] ../source3/lib/access.c:338(allow_access) Allowed connection from 192.168.1.22 (192.168.1.22) [2016/11/28 17:50:45.247530, 10, pid=26868, effective(0, 0), real(0, 0)] ../source3/smbd/process.c:3749(smbd_add_connection) Connection allowed from ipv4:192.168.1.22:49102 to ipv4:192.168.1.24:445 [2016/11/28 17:50:45.247584, 6, pid=26868, effective(0, 0), real(0, 0)] ../source3/param/loadparm.c:2238(lp_file_list_changed) lp_file_list_changed() file /var/etc/smb4.conf -> /var/etc/smb4.conf last mod_time: Mon Nov 28 17:48:50 2016 [2016/11/28 17:50:45.247624, 3, pid=26868, effective(0, 0), real(0, 0), class=locking] ../source3/smbd/oplock.c:1310(init_oplocks) init_oplocks: initializing messages. [2016/11/28 17:50:45.247634, 5, pid=26868, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:446(messaging_register) Registering messaging pointer for type 774 - private_data=0x813057660 [2016/11/28 17:50:45.247645, 5, pid=26868, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:446(messaging_register) Registering messaging pointer for type 778 - private_data=0x813057660 [2016/11/28 17:50:45.247658, 5, pid=26868, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:446(messaging_register) Registering messaging pointer for type 770 - private_data=0x813057660 [2016/11/28 17:50:45.247666, 5, pid=26868, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:446(messaging_register) Registering messaging pointer for type 787 - private_data=0x813057660 [2016/11/28 17:50:45.247675, 5, pid=26868, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:446(messaging_register) Registering messaging pointer for type 779 - private_data=0x813057660 [2016/11/28 17:50:45.247683, 5, pid=26868, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:446(messaging_register) Registering messaging pointer for type 15 - private_data=0x0 [2016/11/28 17:50:45.247692, 5, pid=26868, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:461(messaging_register) Overriding messaging pointer for type 15 - private_data=0x0 [2016/11/28 17:50:45.247700, 5, pid=26868, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:493(messaging_deregister) Deregistering messaging pointer for type 16 - private_data=0x0 [2016/11/28 17:50:45.247709, 5, pid=26868, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:446(messaging_register) Registering messaging pointer for type 16 - private_data=0x813057660 [2016/11/28 17:50:45.247717, 5, pid=26868, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:493(messaging_deregister) Deregistering messaging pointer for type 33 - private_data=0x813046400 [2016/11/28 17:50:45.247725, 5, pid=26868, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:446(messaging_register) Registering messaging pointer for type 33 - private_data=0x813057660 [2016/11/28 17:50:45.247733, 5, pid=26868, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:493(messaging_deregister) Deregistering messaging pointer for type 790 - private_data=0x0 [2016/11/28 17:50:45.247742, 5, pid=26868, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:446(messaging_register) Registering messaging pointer for type 790 - private_data=0x813057660 [2016/11/28 17:50:45.247750, 5, pid=26868, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:493(messaging_deregister) Deregistering messaging pointer for type 791 - private_data=0x0 [2016/11/28 17:50:45.247758, 5, pid=26868, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:493(messaging_deregister) Deregistering messaging pointer for type 1 - private_data=0x0 [2016/11/28 17:50:45.247767, 5, pid=26868, effective(0, 0), real(0, 0)] ../source3/lib/messages.c:446(messaging_register) Registering messaging pointer for type 1 - private_data=0x0 [2016/11/28 17:50:45.247778, 10, pid=26868, effective(0, 0), real(0, 0)] ../source3/lib/events.c:483(event_add_idle) event_add_idle: idle_evt(keepalive) 0x813043d20 [2016/11/28 17:50:45.247787, 10, pid=26868, effective(0, 0), real(0, 0)] ../source3/lib/events.c:483(event_add_idle) event_add_idle: idle_evt(deadtime) 0x813043de0 [2016/11/28 17:50:45.247797, 10, pid=26868, effective(0, 0), real(0, 0)] ../source3/lib/events.c:483(event_add_idle) event_add_idle: idle_evt(housekeeping) 0x813043ea0 [2016/11/28 17:50:46.048062, 0, pid=26853, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:271(winbindd_sig_term_handler) Got sig[15] terminate (is_parent=1) [2016/11/28 17:50:46.053958, 5, pid=26853, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 2 for /mnt/backupdir/samba4/serverid.tdb [2016/11/28 17:50:46.053980, 10, pid=26853, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2:/mnt/backupdir/samba4/serverid.tdb 3: [2016/11/28 17:50:46.053996, 10, pid=26853, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key E568000000000000FFFF [2016/11/28 17:50:46.054010, 10, pid=26853, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x812044560 [2016/11/28 17:50:46.054041, 10, pid=26853, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key E568000000000000FFFF [2016/11/28 17:50:46.054052, 5, pid=26853, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 2 for /mnt/backupdir/samba4/serverid.tdb [2016/11/28 17:50:46.054062, 10, pid=26853, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2: 3: [2016/11/28 17:50:46.061199, 4, pid=26849, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2016/11/28 17:50:46.061222, 5, pid=26849, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2016/11/28 17:50:46.061233, 5, pid=26849, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2016/11/28 17:50:46.061266, 5, pid=26849, 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) [2016/11/28 17:50:46.061278, 4, pid=26849, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2016/11/28 17:50:46.061287, 5, pid=26849, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2016/11/28 17:50:46.061296, 5, pid=26849, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2016/11/28 17:50:46.061314, 5, pid=26849, 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) [2016/11/28 17:50:46.061324, 4, pid=26849, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2016/11/28 17:50:46.061333, 5, pid=26849, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2016/11/28 17:50:46.061342, 5, pid=26849, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2016/11/28 17:50:46.061358, 5, pid=26849, 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) [2016/11/28 17:50:46.061368, 4, pid=26849, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2016/11/28 17:50:46.061378, 5, pid=26849, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2016/11/28 17:50:46.061386, 5, pid=26849, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2016/11/28 17:50:46.061413, 5, pid=26849, 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) [2016/11/28 17:50:46.061428, 5, pid=26849, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:178(dbwrap_check_lock_order) check lock order 2 for /mnt/backupdir/samba4/serverid.tdb [2016/11/28 17:50:46.061438, 10, pid=26849, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2:/mnt/backupdir/samba4/serverid.tdb 3: [2016/11/28 17:50:46.061455, 10, pid=26849, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key E168000000000000FFFF [2016/11/28 17:50:46.061473, 10, pid=26849, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x813043ea0 [2016/11/28 17:50:46.061502, 10, pid=26849, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key E168000000000000FFFF [2016/11/28 17:50:46.061513, 5, pid=26849, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 2 for /mnt/backupdir/samba4/serverid.tdb [2016/11/28 17:50:46.061523, 10, pid=26849, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2: 3: [2016/11/28 17:50:46.061798, 3, pid=26849, effective(0, 0), real(0, 0)] ../source3/smbd/server_exit.c:252(exit_server_common) Server exit (termination signal) [2016/11/28 17:50:46.062006, 4, pid=26868, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2016/11/28 17:50:46.062028, 5, pid=26868, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2016/11/28 17:50:46.062042, 5, pid=26868, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2016/11/28 17:50:46.062068, 5, pid=26868, 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) [2016/11/28 17:50:46.062080, 4, pid=26868, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2016/11/28 17:50:46.062090, 5, pid=26868, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2016/11/28 17:50:46.062099, 5, pid=26868, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2016/11/28 17:50:46.062115, 5, pid=26868, 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) [2016/11/28 17:50:46.062126, 4, pid=26868, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2016/11/28 17:50:46.062135, 5, pid=26868, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2016/11/28 17:50:46.062143, 5, pid=26868, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2016/11/28 17:50:46.062160, 5, pid=26868, 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) [2016/11/28 17:50:46.062171, 10, pid=26868, effective(0, 0), real(0, 0)] ../source3/smbd/smbXsrv_session.c:1642(smbXsrv_session_logoff_all) smbXsrv_session_logoff_all: empty session_table, nothing to do. [2016/11/28 17:50:46.062180, 4, pid=26868, effective(0, 0), real(0, 0)] ../source3/smbd/sec_ctx.c:321(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0 [2016/11/28 17:50:46.062190, 5, pid=26868, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2016/11/28 17:50:46.062198, 5, pid=26868, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2016/11/28 17:50:46.062214, 5, pid=26868, 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) [2016/11/28 17:50:46.062372, 3, pid=26868, effective(0, 0), real(0, 0)] ../source3/smbd/server_exit.c:252(exit_server_common) Server exit (termination signal) [2016/11/28 17:50:46.063735, 5, pid=26856, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2016/11/28 17:50:46.063778, 5, pid=26856, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2016/11/28 17:50:46.063796, 5, pid=26856, 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) [2016/11/28 17:50:46.063942, 3, pid=26856, effective(0, 0), real(0, 0)] ../source3/smbd/server_exit.c:252(exit_server_common) Server exit (termination signal) [2016/11/28 17:50:46.066043, 5, pid=26855, effective(0, 0), real(0, 0)] ../libcli/security/security_token.c:53(security_token_debug) Security token: (NULL) [2016/11/28 17:50:46.066340, 5, pid=26855, effective(0, 0), real(0, 0)] ../source3/auth/token_util.c:639(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2016/11/28 17:50:46.066362, 5, pid=26855, 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) [2016/11/28 17:50:46.066536, 3, pid=26855, effective(0, 0), real(0, 0)] ../source3/smbd/server_exit.c:252(exit_server_common) Server exit (termination signal) [2016/11/28 17:50:47.090498, 10, pid=26846, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Locking key DE68000000000000FFFF [2016/11/28 17:50:47.090790, 10, pid=26846, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal) Allocated locked data 0x0x80f044aa0 [2016/11/28 17:50:47.090816, 10, pid=26846, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key) Unlocking key DE68000000000000FFFF [2016/11/28 17:50:47.090827, 5, pid=26846, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:146(dbwrap_lock_order_state_destructor) release lock order 2 for /mnt/backupdir/samba4/serverid.tdb [2016/11/28 17:50:47.090837, 10, pid=26846, effective(0, 0), real(0, 0)] ../lib/dbwrap/dbwrap.c:133(debug_lock_order) lock order: 1: 2: 3: