Attachment 5609 Details for Bug 33303 – memberserver_wbinfo-n-ARW2008R2+winuser1.log

memberserver_wbinfo-n-ARW2008R2+winuser1.log

memberserver_samba_logs_wbinfo-n-ARW2008R2+winuser1.log (text/plain), 19.53 KB, created by Arvid Requate on 2013-11-12 12:32:31 CET

(hide)

Description:

Filename:

MIME Type:

Creator: Arvid Requate

Created: 2013-11-12 12:32:31 CET

Size: 19.53 KB

patch

obsolete

>diff -Nuar samba.0/log.wb-AR32I8 samba.1/log.wb-AR32I8
>--- samba.0/log.wb-AR32I8	2013-11-05 17:31:29.380000000 +0100
>+++ samba.1/log.wb-AR32I8	2013-11-05 17:31:33.540000000 +0100
>@@ -3083,3 +3083,173 @@
>   Finished processing child request 59
> [2013/11/05 17:30:45.607497, 10, pid=7366, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_dual.c:1358(child_handler)
>   Writing 3532 bytes to parent
>+[2013/11/05 17:31:29.396137, 10, pid=7366, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_dual.c:71(child_read_request)
>+  Need to read 52 extra bytes
>+[2013/11/05 17:31:29.396209,  4, pid=7366, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_dual.c:1333(child_handler)
>+  child daemon request 59
>+[2013/11/05 17:31:29.396253, 10, pid=7366, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_dual.c:458(child_process_request)
>+  child_process_request: request fn NDRCMD
>+[2013/11/05 17:31:29.396296, 10, pid=7366, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_dual_ndr.c:315(winbindd_dual_ndrcmd)
>+  winbindd_dual_ndrcmd: Running command WBINT_LOOKUPNAME (AR32I8)
>+[2013/11/05 17:31:29.396368,  1, pid=7366, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:333(ndr_print_function_debug)
>+       wbint_LookupName: struct wbint_LookupName
>+          in: struct wbint_LookupName
>+              domain                   : *
>+                  domain                   : 'ARW2008R2'
>+              name                     : *
>+                  name                     : 'WINUSER1'
>+              flags                    : 0x00000000 (0)
>+[2013/11/05 17:31:29.396530, 10, pid=7366, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:538(refresh_sequence_number)
>+  refresh_sequence_number: AR32I8 time ok
>+[2013/11/05 17:31:29.396571, 10, pid=7366, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:583(refresh_sequence_number)
>+  refresh_sequence_number: AR32I8 seq number is now 1383669099
>+[2013/11/05 17:31:29.396628, 10, pid=7366, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:1869(name_to_sid)
>+  name_to_sid: [Cached] - doing backend query for name for domain AR32I8
>+[2013/11/05 17:31:29.396673,  3, pid=7366, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_msrpc.c:252(msrpc_name_to_sid)
>+  msrpc_name_to_sid: name=ARW2008R2\WINUSER1
>+[2013/11/05 17:31:29.396715,  3, pid=7366, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_msrpc.c:266(msrpc_name_to_sid)
>+  name_to_sid [rpc] ARW2008R2\WINUSER1 for domain ARW2008R2
>+[2013/11/05 17:31:29.396840,  1, pid=7366, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:333(ndr_print_function_debug)
>+       lsa_LookupNames: struct lsa_LookupNames
>+          in: struct lsa_LookupNames
>+              handle                   : *
>+                  handle: struct policy_handle
>+                      handle_type              : 0x00000000 (0)
>+                      uuid                     : 0000000f-0000-0000-7952-651dae1f0000
>+              num_names                : 0x00000001 (1)
>+              names: ARRAY(1)
>+                  names: struct lsa_String
>+                      length                   : 0x0024 (36)
>+                      size                     : 0x0024 (36)
>+                      string                   : *
>+                          string                   : 'ARW2008R2\WINUSER1'
>+              sids                     : *
>+                  sids: struct lsa_TransSidArray
>+                      count                    : 0x00000000 (0)
>+                      sids                     : NULL
>+              level                    : LSA_LOOKUP_NAMES_ALL (1)
>+              count                    : *
>+                  count                    : 0x00000000 (0)
>+[2013/11/05 17:31:29.397273,  1, pid=7366, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:296(ndr_print_debug)
>+       &r: struct ncacn_packet
>+          rpc_vers                 : 0x05 (5)
>+          rpc_vers_minor           : 0x00 (0)
>+          ptype                    : DCERPC_PKT_REQUEST (0)
>+          pfc_flags                : 0x03 (3)
>+          drep: ARRAY(4)
>+              [0]                      : 0x10 (16)
>+              [1]                      : 0x00 (0)
>+              [2]                      : 0x00 (0)
>+              [3]                      : 0x00 (0)
>+          frag_length              : 0x0018 (24)
>+          auth_length              : 0x0010 (16)
>+          call_id                  : 0x00000011 (17)
>+          u                        : union dcerpc_payload(case 0)
>+          request: struct dcerpc_request
>+              alloc_hint               : 0x00000064 (100)
>+              context_id               : 0x0000 (0)
>+              opnum                    : 0x000e (14)
>+              object                   : union dcerpc_object(case 0)
>+              empty: struct dcerpc_empty
>+              _pad                     : DATA_BLOB length=0
>+              stub_and_verifier        : DATA_BLOB length=0
>+[2013/11/05 17:31:29.397788,  1, pid=7366, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:296(ndr_print_debug)
>+       &r: struct dcerpc_auth
>+          auth_type                : DCERPC_AUTH_TYPE_SPNEGO (9)
>+          auth_level               : DCERPC_AUTH_LEVEL_PRIVACY (6)
>+          auth_pad_length          : 0x04 (4)
>+          auth_reserved            : 0x00 (0)
>+          auth_context_id          : 0x00000001 (1)
>+          credentials              : DATA_BLOB length=0
>+[2013/11/05 17:31:29.397940, 10, pid=7366, effective(0, 0), real(0, 0)] ../auth/ntlmssp/ntlmssp_sign.c:287(ntlmssp_seal_packet)
>+  ntlmssp_seal_data: seal
>+[2013/11/05 17:31:29.397998,  5, pid=7366, effective(0, 0), real(0, 0), class=rpc_cli] ../source3/rpc_client/cli_pipe.c:741(rpc_api_pipe_send)
>+  rpc_api_pipe: host BACKUP41
>+[2013/11/05 17:31:29.398080, 10, pid=7366, effective(0, 0), real(0, 0)] ../libcli/smb/smb1cli_trans.c:334(smb1cli_trans_format)
>+  num_setup=2, max_setup=0, param_total=0, this_param=0, max_param=0, data_total=152, this_data=152, max_data=4280, param_offset=84, param_pad=2, param_disp=0, data_offset=84, data_pad=0, data_disp=0
>+[2013/11/05 17:31:33.528188,  5, pid=7366, effective(0, 0), real(0, 0), class=rpc_cli] ../source3/rpc_client/cli_pipe.c:100(rpc_read_send)
>+  rpc_read_send: data_to_read: 80
>+[2013/11/05 17:31:33.528585,  1, pid=7366, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:296(ndr_print_debug)
>+       r: struct ncacn_packet
>+          rpc_vers                 : 0x05 (5)
>+          rpc_vers_minor           : 0x00 (0)
>+          ptype                    : DCERPC_PKT_RESPONSE (2)
>+          pfc_flags                : 0x03 (3)
>+          drep: ARRAY(4)
>+              [0]                      : 0x10 (16)
>+              [1]                      : 0x00 (0)
>+              [2]                      : 0x00 (0)
>+              [3]                      : 0x00 (0)
>+          frag_length              : 0x0060 (96)
>+          auth_length              : 0x0010 (16)
>+          call_id                  : 0x00000011 (17)
>+          u                        : union dcerpc_payload(case 2)
>+          response: struct dcerpc_response
>+              alloc_hint               : 0x00000030 (48)
>+              context_id               : 0x0000 (0)
>+              cancel_count             : 0x00 (0)
>+              _pad                     : DATA_BLOB length=1
>+  [0000] 00                                                . 
>+              stub_and_verifier        : DATA_BLOB length=72
>+  [0000] DF 53 42 E0 3A A8 AA FB   81 66 4E 44 94 7E B3 71   .SB.:... .fND.~.q
>+  [0010] CD F9 65 44 F9 4C 2E E8   70 FC C8 23 AE E8 C5 D5   ..eD.L.. p..#....
>+  [0020] F7 DE 59 A5 BC C4 D0 50   07 C3 BB DF 54 A3 27 67   ..Y....P ....T.'g
>+  [0030] 09 06 00 00 01 00 00 00   01 00 00 00 FF 11 E6 98   ........ ........
>+  [0040] 6C 7A 4A 9D 03 00 00 00                            lzJ..... 
>+[2013/11/05 17:31:33.530129, 10, pid=7366, effective(0, 0), real(0, 0), class=rpc_parse] ../source3/librpc/rpc/dcerpc_helpers.c:652(dcerpc_check_auth)
>+  Requested Privacy.
>+[2013/11/05 17:31:33.530239,  6, pid=7366, effective(0, 0), real(0, 0)] ../librpc/rpc/dcerpc_util.c:140(dcerpc_pull_auth_trailer)
>+  ../librpc/rpc/dcerpc_util.c:140: auth_pad_length 0
>+[2013/11/05 17:31:33.530340, 10, pid=7366, effective(0, 0), real(0, 0), class=rpc_parse] ../source3/librpc/rpc/dcerpc_helpers.c:713(dcerpc_check_auth)
>+  GENSEC auth
>+[2013/11/05 17:31:33.530446, 10, pid=7366, effective(0, 0), real(0, 0)] ../auth/ntlmssp/ntlmssp_sign.c:371(ntlmssp_unseal_packet)
>+  ntlmssp_unseal_packet: seal
>+[2013/11/05 17:31:33.530564, 10, pid=7366, effective(0, 0), real(0, 0)] ../auth/ntlmssp/ntlmssp_sign.c:255(ntlmssp_check_packet)
>+  ntlmssp_check_packet: NTLMSSP signature OK !
>+[2013/11/05 17:31:33.530666, 10, pid=7366, effective(0, 0), real(0, 0), class=rpc_cli] ../source3/rpc_client/cli_pipe.c:440(cli_pipe_validate_current_pdu)
>+  Got pdu len 96, data_len 48, ss_len 0
>+[2013/11/05 17:31:33.530767, 10, pid=7366, effective(0, 0), real(0, 0), class=rpc_cli] ../source3/rpc_client/cli_pipe.c:885(rpc_api_pipe_got_pdu)
>+  rpc_api_pipe: got frag len of 96 at offset 0: NT_STATUS_OK
>+[2013/11/05 17:31:33.530868, 10, pid=7366, effective(0, 0), real(0, 0), class=rpc_cli] ../source3/rpc_client/cli_pipe.c:940(rpc_api_pipe_got_pdu)
>+  rpc_api_pipe: host BACKUP41 returned 48 bytes.
>+[2013/11/05 17:31:33.531015,  1, pid=7366, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:333(ndr_print_function_debug)
>+       lsa_LookupNames: struct lsa_LookupNames
>+          out: struct lsa_LookupNames
>+              domains                  : *
>+                  domains                  : *
>+                      domains: struct lsa_RefDomainList
>+                          count                    : 0x00000000 (0)
>+                          domains                  : NULL
>+                          max_size                 : 0x00000000 (0)
>+              sids                     : *
>+                  sids: struct lsa_TransSidArray
>+                      count                    : 0x00000001 (1)
>+                      sids                     : *
>+                          sids: ARRAY(1)
>+                              sids: struct lsa_TranslatedSid
>+                                  sid_type                 : SID_NAME_UNKNOWN (8)
>+                                  rid                      : 0x00000000 (0)
>+                                  sid_index                : 0xffffffff (4294967295)
>+              count                    : *
>+                  count                    : 0x00000000 (0)
>+              result                   : NT_STATUS_NONE_MAPPED
>+[2013/11/05 17:31:33.532056, 10, pid=7366, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:538(refresh_sequence_number)
>+  refresh_sequence_number: AR32I8 time ok
>+[2013/11/05 17:31:33.532165, 10, pid=7366, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:583(refresh_sequence_number)
>+  refresh_sequence_number: AR32I8 seq number is now 1383669099
>+[2013/11/05 17:31:33.532396, 10, pid=7366, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:961(wcache_save_name_to_sid)
>+  wcache_save_name_to_sid: ARW2008R2\WINUSER1 -> S-0-0 (NT_STATUS_NONE_MAPPED)
>+[2013/11/05 17:31:33.532553, 10, pid=7366, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cache.c:991(wcache_save_sid_to_name)
>+  wcache_save_sid_to_name: S-0-0 -> ARW2008R2\winuser1 (NT_STATUS_NONE_MAPPED)
>+[2013/11/05 17:31:33.532662,  1, pid=7366, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:333(ndr_print_function_debug)
>+       wbint_LookupName: struct wbint_LookupName
>+          out: struct wbint_LookupName
>+              type                     : *
>+                  type                     : SID_NAME_USE_NONE (0)
>+              sid                      : *
>+                  sid                      : S-0-0
>+              result                   : NT_STATUS_NONE_MAPPED
>+[2013/11/05 17:31:33.533058,  4, pid=7366, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_dual.c:1341(child_handler)
>+  Finished processing child request 59
>+[2013/11/05 17:31:33.533160, 10, pid=7366, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_dual.c:1358(child_handler)
>+  Writing 3512 bytes to parent
>diff -Nuar samba.0/log.winbindd samba.1/log.winbindd
>--- samba.0/log.winbindd	2013-11-05 17:31:29.384000000 +0100
>+++ samba.1/log.winbindd	2013-11-05 17:31:33.540000000 +0100
>@@ -1368,3 +1368,79 @@
>   winbind_client_response_written[7369:LOOKUPNAME]: delivered response to client
> [2013/11/05 17:30:45.612297,  6, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:918(winbind_client_request_read)
>   closing socket 25, client exited
>+[2013/11/05 17:31:29.393648,  6, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:870(new_connection)
>+  accepted socket 22
>+[2013/11/05 17:31:29.393943, 10, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:720(process_request)
>+  process_request: request fn INTERFACE_VERSION
>+[2013/11/05 17:31:29.393999,  3, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_misc.c:395(winbindd_interface_version)
>+  [ 7397]: request interface version
>+[2013/11/05 17:31:29.394074, 10, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:816(winbind_client_response_written)
>+  winbind_client_response_written[7397:INTERFACE_VERSION]: delivered response to client
>+[2013/11/05 17:31:29.394166, 10, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:720(process_request)
>+  process_request: request fn WINBINDD_PRIV_PIPE_DIR
>+[2013/11/05 17:31:29.394210,  3, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_misc.c:428(winbindd_priv_pipe_dir)
>+  [ 7397]: request location of privileged pipe
>+[2013/11/05 17:31:29.394285, 10, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:816(winbind_client_response_written)
>+  winbind_client_response_written[7397:WINBINDD_PRIV_PIPE_DIR]: delivered response to client
>+[2013/11/05 17:31:29.394383,  6, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:870(new_connection)
>+  accepted socket 25
>+[2013/11/05 17:31:29.394461,  6, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:918(winbind_client_request_read)
>+  closing socket 22, client exited
>+[2013/11/05 17:31:29.394546, 10, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:720(process_request)
>+  process_request: request fn INTERFACE_VERSION
>+[2013/11/05 17:31:29.394590,  3, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_misc.c:395(winbindd_interface_version)
>+  [ 7397]: request interface version
>+[2013/11/05 17:31:29.394647, 10, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:816(winbind_client_response_written)
>+  winbind_client_response_written[7397:INTERFACE_VERSION]: delivered response to client
>+[2013/11/05 17:31:29.394730, 10, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:720(process_request)
>+  process_request: request fn INFO
>+[2013/11/05 17:31:29.394816,  3, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_misc.c:383(winbindd_info)
>+  [ 7397]: request misc info
>+[2013/11/05 17:31:29.394967, 10, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:816(winbind_client_response_written)
>+  winbind_client_response_written[7397:INFO]: delivered response to client
>+[2013/11/05 17:31:29.395069, 10, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:720(process_request)
>+  process_request: request fn NETBIOS_NAME
>+[2013/11/05 17:31:29.395115,  3, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_misc.c:416(winbindd_netbios_name)
>+  [ 7397]: request netbios name
>+[2013/11/05 17:31:29.395172, 10, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:816(winbind_client_response_written)
>+  winbind_client_response_written[7397:NETBIOS_NAME]: delivered response to client
>+[2013/11/05 17:31:29.395254, 10, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:720(process_request)
>+  process_request: request fn DOMAIN_NAME
>+[2013/11/05 17:31:29.395299,  3, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_misc.c:405(winbindd_domain_name)
>+  [ 7397]: request domain name
>+[2013/11/05 17:31:29.395377, 10, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:816(winbind_client_response_written)
>+  winbind_client_response_written[7397:DOMAIN_NAME]: delivered response to client
>+[2013/11/05 17:31:29.395466, 10, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:720(process_request)
>+  process_request: request fn DOMAIN_INFO
>+[2013/11/05 17:31:29.395510,  3, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_misc.c:237(winbindd_domain_info)
>+  [ 7397]: domain_info [AR32I8]
>+[2013/11/05 17:31:29.395577, 10, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:816(winbind_client_response_written)
>+  winbind_client_response_written[7397:DOMAIN_INFO]: delivered response to client
>+[2013/11/05 17:31:29.395718, 10, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:693(process_request)
>+  process_request: Handling async request 7397:LOOKUPNAME
>+[2013/11/05 17:31:29.395814,  3, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_lookupname.c:69(winbindd_lookupname_send)
>+  lookupname ARW2008R2+winuser1
>+[2013/11/05 17:31:29.395886,  1, pid=7364, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:333(ndr_print_function_debug)
>+       wbint_LookupName: struct wbint_LookupName
>+          in: struct wbint_LookupName
>+              domain                   : *
>+                  domain                   : 'ARW2008R2'
>+              name                     : *
>+                  name                     : 'WINUSER1'
>+              flags                    : 0x00000000 (0)
>+[2013/11/05 17:31:33.533642,  1, pid=7364, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:333(ndr_print_function_debug)
>+       wbint_LookupName: struct wbint_LookupName
>+          out: struct wbint_LookupName
>+              type                     : *
>+                  type                     : SID_NAME_USE_NONE (0)
>+              sid                      : *
>+                  sid                      : S-0-0
>+              result                   : NT_STATUS_NONE_MAPPED
>+[2013/11/05 17:31:33.534094,  5, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_lookupname.c:104(winbindd_lookupname_recv)
>+  Could not convert sid S-0-0: NT_STATUS_NONE_MAPPED
>+[2013/11/05 17:31:33.534210, 10, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:755(wb_request_done)
>+  wb_request_done[7397:LOOKUPNAME]: NT_STATUS_NONE_MAPPED
>+[2013/11/05 17:31:33.537523, 10, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:816(winbind_client_response_written)
>+  winbind_client_response_written[7397:LOOKUPNAME]: delivered response to client
>+[2013/11/05 17:31:33.537922,  6, pid=7364, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:918(winbind_client_request_read)
>+  closing socket 25, client exited

Actions: View

Attachments on bug 33303: 5607 | 5608 | 5609 | 5612