make test spin / Having trouble debugging samba on FreeBSD (threads)

Mon Oct 1 04:30:26 MDT 2012

On Sun, Sep 30, 2012 at 09:13:34AM +1000, Andrew Bartlett wrote:
> I've been for some time puzzled as to why the build farm fails quite so
> many tests, with name resolution errors.
> 
> I first thought it was to do with samba_dnsupdate not locking the
> dns_hosts_file, so I reworked that code to have much more certain
> locking behaviour.
> 
> Noticing that one of the failing platforms is FreeBSD, I've reproduced
> it here on 8.2.  When I run make test or make testenv I get: 
> 
> /usr/local/samba-build/source4/scripting/bin/samba_dnsupdate: Traceback
> (most recent call last):
> /usr/local/samba-build/source4/scripting/bin/samba_dnsupdate:   File
> "/usr/local/samba-build/source4/scripting/bin/samba_dnsupdate", line
> 507, in <module>
> /usr/local/samba-build/source4/scripting/bin/samba_dnsupdate:
> get_credentials(lp)
> /usr/local/samba-build/source4/scripting/bin/samba_dnsupdate:   File
> "/usr/local/samba-build/source4/scripting/bin/samba_dnsupdate", line
> 121, in get_credentials
> /usr/local/samba-build/source4/scripting/bin/samba_dnsupdate:
> creds.get_named_ccache(lp, ccachename)
> /usr/local/samba-build/source4/scripting/bin/samba_dnsupdate:
> RuntimeError: kinit for LOCALDC$@SAMBA.EXAMPLE.COM failed (Cannot
> contact any KDC for requested realm)
> 
> For some reason the kdc, cldapd, dns and echo tasks spin:
> 
> /usr/local/samba-build/source4/scripting/bin/samba_dnsupdate: 
> 97782   2  S+     0:00.00 samba: task[dcesrv] (samba)
> 97783   2  I+     0:00.01 samba: task[nbtd] (samba)
> 97784   2  S+     0:00.01 samba: task[wreplsrv] (samba)
> 97785   2  S+     0:00.01 samba: task[ldapsrv] (samba)
> 97786   2  R+     0:15.38 samba: task[cldapd] (samba)
> 97787   2  R+     0:13.64 samba: task[kdc] (samba)
> 97788   2  S+     0:00.04 samba: task[dreplsrv] (samba)
> 97789   2  S+     0:00.00 samba: task[winbind] (samba)
> 97790   2  S+     0:00.00 samba: task[ntp_signd] (samba)
> 97791   2  I+     0:00.09 samba: task[kccsrv] (samba)
> 97792   2  S+     0:00.01 samba: task[dnsupdate] (samba)
> 97793   2  R+     0:15.75 samba: task[dns] (samba)
> 97794   2  R+     0:15.58 samba: task[echo] (samba)
> 97795   2  S+     0:00.00 samba: task[smbsrv] (samba)
> 
> What I need help with is running gdb on samba.  I know it sounds silly,
> but neither gdb, nor gdb72 will attach to the process (gdb -p <PID>),
> each giving internal assertions on threads.  Is there a different
> debugger I should use, or should I try a newer FreeBSD than 8.2?  I
> already tried compiling with --disable-pthredpool.
> 
> Volker:
> 
> Does the full (top level) 'make test' pass for you in your FreeBSD
> development environment?

No, it does not. I have spinning samba processes as well.
They are spinning in a loop:

  7738 samba    RET   recvfrom 0
  7738 samba    CALL  ioctl(0x13,FIONREAD,0x7fffffff6774)
  7738 samba    CALL  ioctl(0x13,FIONREAD,0x7fffffff6774)
  7738 samba    RET   ioctl 0
  7738 samba    CALL getsockopt(0x13,SOL_SOCKET,SO_ERROR,0x7fffffff6778,0x7fffffff6770)
  7738 samba    CALL getsockopt(0x13,SOL_SOCKET,SO_ERROR,0x7fffffff6778,0x7fffffff6770)
  7738 samba    RET   getsockopt 0
  7738 samba    CALL recvfrom(0x13,0x80d8196a0,0,0,0x7fffffff6700,0x7fffffff66fc)
  7738 samba    CALL recvfrom(0x13,0x80d8196a0,0,0,0x7fffffff6700,0x7fffffff66fc)
  7738 samba    GIO   fd 19 read 0 bytes
       ""
  7738 samba    RET   recvfrom 0

This repeats for multiple file descriptors, all of which
are unix domain datagram sockets:

root     samba      7738  19 dgram /root/git/s3/st/w/U150058

Please note that there is no poll-like call in that ktrace
output.

A sample backtrace is:

#0  0x00000008075e324b in find_socket_info (fd=19) at ../lib/socket_wrapper/socket_wrapper.c:594
#1  0x00000008075e55a1 in swrap_getsockopt (s=19, level=65535, optname=4103, optval=0x7fffffff6778, optlen=0x7fffffff6770) at ../lib/socket_wrapper/socket_wrapper.c:1882
#2  0x0000000806fb58b2 in tsocket_bsd_pending (fd=19) at ../lib/tsocket/tsocket_bsd.c:179
#3  0x0000000806fb6af3 in tdgram_bsd_recvfrom_handler (private_data=0x80db94690) at ../lib/tsocket/tsocket_bsd.c:878
#4  0x0000000806fb69f1 in tdgram_bsd_recvfrom_send (mem_ctx=0x821023e50, ev=0x80d824550, dgram=0x821023d50) at ../lib/tsocket/tsocket_bsd.c:845
#5  0x0000000806fb38dc in tdgram_recvfrom_send (mem_ctx=0x80daf2640, ev=0x80d824550, dgram=0x821023d50) at ../lib/tsocket/tsocket.c:208
#6  0x0000000816f7402c in kdc_udp_call_loop (subreq=0x0) at ../source4/kdc/kdc.c:569
#7  0x0000000801fc6991 in _tevent_req_notify_callback (req=0x80db94510, location=0x806fbc4c4 "../lib/tsocket/tsocket.c:233") at ../lib/tevent/tevent_req.c:101
#8  0x0000000801fc69ca in tevent_req_finish (req=0x80db94510, state=TEVENT_REQ_USER_ERROR, location=0x806fbc4c4 "../lib/tsocket/tsocket.c:233") at ../lib/tevent/tevent_req.c:110
#9  0x0000000801fc6a42 in _tevent_req_error (req=0x80db94510, error=12, location=0x806fbc4c4 "../lib/tsocket/tsocket.c:233") at ../lib/tevent/tevent_req.c:128
#10 0x0000000806fb39e0 in tdgram_recvfrom_done (subreq=0x80db94690) at ../lib/tsocket/tsocket.c:233
#11 0x0000000801fc6991 in _tevent_req_notify_callback (req=0x80db94690, location=0x806fbd690 "../lib/tsocket/tsocket_bsd.c:928") at ../lib/tevent/tevent_req.c:101
#12 0x0000000801fc69ca in tevent_req_finish (req=0x80db94690, state=TEVENT_REQ_NO_MEMORY, location=0x806fbd690 "../lib/tsocket/tsocket_bsd.c:928") at ../lib/tevent/tevent_req.c:110
#13 0x0000000801fc6b00 in tevent_req_trigger (ev=0x80d824550, im=0x80db94750, private_data=0x80db94690) at ../lib/tevent/tevent_req.c:166
#14 0x0000000801fc5e98 in tevent_common_loop_immediate (ev=0x80d824550) at ../lib/tevent/tevent_immediate.c:135
#15 0x0000000801fc9ce1 in std_event_loop_once (ev=0x80d824550, location=0x800aaf770 "../lib/ldb/common/ldb.c:616") at ../lib/tevent/tevent_standard.c:555
#16 0x0000000801fc4f5f in _tevent_loop_once (ev=0x80d824550, location=0x800aaf770 "../lib/ldb/common/ldb.c:616") at ../lib/tevent/tevent.c:507
#17 0x0000000800aa5e1b in ldb_wait (handle=0x8213d21d0, type=LDB_WAIT_ALL) at ../lib/ldb/common/ldb.c:616
#18 0x0000000817ff58e3 in dsdb_module_search_dn (module=0x80d9a8450, mem_ctx=0x80d819600, _res=0x7fffffff6c50, basedn=0x82214eb90, attrs=0x818200660, dsdb_flags=1048576, parent=0x82214ea10) at ../source4/dsdb/samdb/ldb_modules/util.c:92
#19 0x0000000817ff85fd in dsdb_module_find_dsheuristics (module=0x80d9a8450, mem_ctx=0x80d819600, parent=0x82214ea10) at ../source4/dsdb/samdb/ldb_modules/util.c:1269
#20 0x0000000817ff872e in dsdb_user_password_support (module=0x80d9a8450, mem_ctx=0x8213d1f50, parent=0x82214ea10) at ../source4/dsdb/samdb/ldb_modules/util.c:1309
#21 0x0000000817def4c0 in acl_search (module=0x80d9a8450, req=0x82214ea10) at ../source4/dsdb/samdb/ldb_modules/acl.c:1496
#22 0x0000000800a88534 in ldb_next_request (module=0x80d9a8450, request=0x82214ea10) at ../lib/ldb/common/ldb_modules.c:523
#23 0x000000081880d77b in descriptor_search (module=0x80d9a84d0, req=0x82214ea10) at ../source4/dsdb/samdb/ldb_modules/descriptor.c:744
#24 0x0000000800a88534 in ldb_next_request (module=0x80d9a84d0, request=0x82214ea10) at ../lib/ldb/common/ldb_modules.c:523
#25 0x0000000818c19a69 in extended_dn_in_fix (module=0x80d9a85d0, req=0x82214ea10, dn=0x82214ead0) at ../source4/dsdb/samdb/ldb_modules/extended_dn_in.c:554
#26 0x0000000818c1a0a5 in extended_dn_in_search (module=0x80d9a85d0, req=0x82214ea10) at ../source4/dsdb/samdb/ldb_modules/extended_dn_in.c:682
#27 0x0000000800a88534 in ldb_next_request (module=0x80d9a85d0, request=0x82214ea10) at ../lib/ldb/common/ldb_modules.c:523
#28 0x0000000818608935 in asq_search (module=0x80d9a86d0, req=0x82214ea10) at ../lib/ldb/modules/asq.c:362
#29 0x0000000800a88534 in ldb_next_request (module=0x80d9a86d0, request=0x82214ea10) at ../lib/ldb/common/ldb_modules.c:523
#30 0x000000081ced57f8 in server_sort_search (module=0x80d9a8750, req=0x82214ea10) at ../lib/ldb/modules/sort.c:267
#31 0x0000000800a88534 in ldb_next_request (module=0x80d9a8750, request=0x82214ea10) at ../lib/ldb/common/ldb_modules.c:523
#32 0x0000000818405a23 in anr_search (module=0x80d9a87d0, req=0x82214ea10) at ../source4/dsdb/samdb/ldb_modules/anr.c:347
#33 0x0000000800a88534 in ldb_next_request (module=0x80d9a87d0, request=0x82214ea10) at ../lib/ldb/common/ldb_modules.c:523
#34 0x000000081b2777f1 in rr_search (module=0x80d9a8850, req=0x82214ea10) at ../source4/dsdb/samdb/ldb_modules/ranged_results.c:261
#35 0x0000000800a88534 in ldb_next_request (module=0x80d9a8850, request=0x82214ea10) at ../lib/ldb/common/ldb_modules.c:523
#36 0x000000081aa5693b in paged_search (module=0x80d9a88d0, req=0x82214ea10) at ../lib/ldb/modules/paged_results.c:311
#37 0x0000000800a88534 in ldb_next_request (module=0x80d9a88d0, request=0x82214ea10) at ../lib/ldb/common/ldb_modules.c:523
#38 0x0000000818a13cc5 in dirsync_ldb_search (module=0x80d9a8950, req=0x82214ea10) at ../source4/dsdb/samdb/ldb_modules/dirsync.c:1000
#39 0x0000000800a88534 in ldb_next_request (module=0x80d9a8950, request=0x82214ea10) at ../lib/ldb/common/ldb_modules.c:523
#40 0x000000081962bbf1 in unlazy_op (module=0x80d9a89d0, req=0x82214ea10) at ../source4/dsdb/samdb/ldb_modules/lazy_commit.c:40
#41 0x0000000800a88534 in ldb_next_request (module=0x80d9a89d0, request=0x82214ea10) at ../lib/ldb/common/ldb_modules.c:523
#42 0x000000081cace67b in schema_search (module=0x80d9a8a50, req=0x82214ea10) at ../source4/dsdb/samdb/ldb_modules/schema_load.c:413
#43 0x0000000800a88534 in ldb_next_request (module=0x80d9a8a50, request=0x82214ea10) at ../lib/ldb/common/ldb_modules.c:523
#44 0x000000081ba9ff1c in rootdse_search (module=0x80d9a8ad0, req=0x82214ea10) at ../source4/dsdb/samdb/ldb_modules/rootdse.c:760
#45 0x0000000800a88534 in ldb_next_request (module=0x80d9a8ad0, request=0x82214ea10) at ../lib/ldb/common/ldb_modules.c:523
#46 0x000000081b897fa2 in resolve_oids_search (module=0x80d9a8b50, req=0x82214ea10) at ../source4/dsdb/samdb/ldb_modules/resolve_oids.c:499
#47 0x0000000800aa6893 in ldb_request (ldb=0x80d824750, req=0x82214ea10) at ../lib/ldb/common/ldb.c:884
#48 0x0000000802a77b63 in dsdb_search (ldb=0x80d824750, mem_ctx=0x80d819560, _res=0x7fffffff7d88, basedn=0x0, scope=LDB_SCOPE_SUBTREE, attrs=0x7fffffff7dc0, dsdb_flags=1, exp_fmt=0x8036c280d "%s") at ../source4/dsdb/common/util.c:3983
#49 0x00000008036bad7d in DsCrackNameOneFilter (sam_ctx=0x80d824750, mem_ctx=0x80d819560, smb_krb5_context=0x8225b73e0, format_flags=0, format_offered=DRSUAPI_DS_NAME_FORMAT_USER_PRINCIPAL, format_desired=DRSUAPI_DS_NAME_FORMAT_FQDN_1779, name_dn=0x0, name=0x80d952f20 "LOCALDC$@SAMBA.EXAMPLE.COM", domain_filter=0x0, result_filter=0x80db94f90 "(&(objectClass=user)(userPrincipalName=LOCALDC$@SAMBA.EXAMPLE.COM))", info1=0x7fffffff8450, scope=2, search_dn=0x0) at ../source4/dsdb/samdb/cracknames.c:949
#50 0x00000008036ba85f in DsCrackNameOneName (sam_ctx=0x80d824750, mem_ctx=0x80d819560, format_flags=0, format_offered=DRSUAPI_DS_NAME_FORMAT_USER_PRINCIPAL, format_desired=DRSUAPI_DS_NAME_FORMAT_FQDN_1779, name=0x80d952f20 "LOCALDC$@SAMBA.EXAMPLE.COM", info1=0x7fffffff8450) at ../source4/dsdb/samdb/cracknames.c:777
#51 0x00000008036bbc03 in crack_user_principal_name (sam_ctx=0x80d824750, mem_ctx=0x80d819560, user_principal_name=0x80d952f20 "LOCALDC$@SAMBA.EXAMPLE.COM", user_dn=0x7fffffff8538, domain_dn=0x7fffffff8698) at ../source4/dsdb/samdb/cracknames.c:1219
#52 0x00000008036c0eed in sam_get_results_principal (sam_ctx=0x80d824750, mem_ctx=0x80d819420, principal=0x80d952f20 "LOCALDC$@SAMBA.EXAMPLE.COM", attrs=0x8038c6bc0, domain_dn=0x7fffffff8698, msg=0x7fffffff8690) at ../source4/auth/sam.c:487
#53 0x00000008179e0e79 in samba_kdc_lookup_client (context=0x80d910e00, kdc_db_ctx=0x80db93d90, mem_ctx=0x80d819420, principal=0x80d952ec0, attrs=0x8038c6bc0, realm_dn=0x7fffffff8698, msg=0x7fffffff8690) at ../source4/kdc/db-glue.c:1122
#54 0x00000008179e0f40 in samba_kdc_fetch_client (context=0x80d910e00, kdc_db_ctx=0x80db93d90, mem_ctx=0x80d819420, principal=0x80d952ec0, flags=4101, entry_ex=0x80db94e80) at ../source4/kdc/db-glue.c:1147
#55 0x00000008179e196a in samba_kdc_fetch (context=0x80d910e00, kdc_db_ctx=0x80db93d90, principal=0x80d952ec0, flags=4101, kvno=0, entry_ex=0x80db94e80) at ../source4/kdc/db-glue.c:1451
#56 0x00000008173b5117 in hdb_samba4_fetch_kvno (context=0x80d910e00, db=0x80d910f90, principal=0x80d952ec0, flags=4101, kvno=0, entry_ex=0x80db94e80) at ../source4/kdc/hdb-samba4.c:92
#57 0x000000081719756c in _kdc_db_fetch (context=0x80d910e00, config=0x80db93c80, principal=0x80d952ec0, flags=4100, kvno_ptr=0x0, db=0x7fffffff8bc8, h=0x7fffffff8bd8) at ../source4/heimdal/kdc/misc.c:94
#58 0x000000081718aae0 in _kdc_as_rep (context=0x80d910e00, config=0x80db93c80, req=0x7fffffff8d80, req_buffer=0x7fffffff8e70, reply=0x7fffffff8f00, from=0x80daf2f00 "ipv4:127.0.0.21:17748", from_addr=0x7fffffff8f10, datagram_reply=1) at ../source4/heimdal/kdc/kerberos5.c:1057
#59 0x000000081719794b in kdc_as_req (context=0x80d910e00, config=0x80db93c80, req_buffer=0x7fffffff8e70, reply=0x7fffffff8f00, from=0x80daf2f00 "ipv4:127.0.0.21:17748", addr=0x7fffffff8f10, datagram_reply=1, claim=0x7fffffff8e6c) at ../source4/heimdal/kdc/process.c:70
#60 0x0000000817197bfe in krb5_kdc_process_krb5_request (context=0x80d910e00, config=0x80db93c80, buf=0x80d903250 "j\201�0\201��\003\002\001\005�\003\002\001\n�\201\2270\201\224�\a\003\005", len=170, reply=0x7fffffff8f00, from=0x80daf2f00 "ipv4:127.0.0.21:17748", addr=0x7fffffff8f10, datagram_reply=1) at ../source4/heimdal/kdc/process.c:242
#61 0x0000000816f7307d in kdc_process (kdc=0x80dbbbed0, mem_ctx=0x8213d1bd0, input=0x8213d1be0, reply=0x8213d1bf0, peer_addr=0x80daf2f70, my_addr=0x80daf2d40, datagram_reply=1) at ../source4/kdc/kdc.c:161
#62 0x0000000816f73e65 in kdc_udp_call_loop (subreq=0x0) at ../source4/kdc/kdc.c:519
#63 0x0000000801fc6991 in _tevent_req_notify_callback (req=0x80db94ed0, location=0x806fbc4e1 "../lib/tsocket/tsocket.c:239") at ../lib/tevent/tevent_req.c:101
#64 0x0000000801fc69ca in tevent_req_finish (req=0x80db94ed0, state=TEVENT_REQ_DONE, location=0x806fbc4e1 "../lib/tsocket/tsocket.c:239") at ../lib/tevent/tevent_req.c:110
#65 0x0000000801fc69f2 in _tevent_req_done (req=0x80db94ed0, location=0x806fbc4e1 "../lib/tsocket/tsocket.c:239") at ../lib/tevent/tevent_req.c:116
#66 0x0000000806fb39fe in tdgram_recvfrom_done (subreq=0x82214e110) at ../lib/tsocket/tsocket.c:239
#67 0x0000000801fc6991 in _tevent_req_notify_callback (req=0x82214e110, location=0x806fbd6b8 "../lib/tsocket/tsocket_bsd.c:933") at ../lib/tevent/tevent_req.c:101
#68 0x0000000801fc69ca in tevent_req_finish (req=0x82214e110, state=TEVENT_REQ_DONE, location=0x806fbd6b8 "../lib/tsocket/tsocket_bsd.c:933") at ../lib/tevent/tevent_req.c:110
#69 0x0000000801fc6b00 in tevent_req_trigger (ev=0x80d824550, im=0x82214e290, private_data=0x82214e110) at ../lib/tevent/tevent_req.c:166
#70 0x0000000801fc5e98 in tevent_common_loop_immediate (ev=0x80d824550) at ../lib/tevent/tevent_immediate.c:135
#71 0x0000000801fc9ce1 in std_event_loop_once (ev=0x80d824550, location=0x810951818 "../source4/smbd/process_standard.c:186") at ../lib/tevent/tevent_standard.c:555
#72 0x0000000801fc4f5f in _tevent_loop_once (ev=0x80d824550, location=0x810951818 "../source4/smbd/process_standard.c:186") at ../lib/tevent/tevent.c:507
#73 0x0000000801fc518f in tevent_common_loop_wait (ev=0x80d824550, location=0x810951818 "../source4/smbd/process_standard.c:186") at ../lib/tevent/tevent.c:608
#74 0x0000000801fc5255 in _tevent_loop_wait (ev=0x80d824550, location=0x810951818 "../source4/smbd/process_standard.c:186") at ../lib/tevent/tevent.c:627
#75 0x0000000810951428 in standard_new_task (ev=0x80d824550, lp_ctx=0x80d83b850, service_name=0x816f79887 "kdc", new_task=0x801755640 <task_server_callback>, private_data=0x82102a4b0) at ../source4/smbd/process_standard.c:186
#76 0x00000008017557f0 in task_server_startup (event_ctx=0x80d824550, lp_ctx=0x80d83b850, service_name=0x816f79887 "kdc", model_ops=0x810b51a80, task_init=0x816f74c80 <kdc_task_init>) at ../source4/smbd/service_task.c:110
#77 0x0000000801753e21 in server_service_init (name=0x80d87a870 "kdc", event_context=0x80d824550, lp_ctx=0x80d83b850, model_ops=0x810b51a80) at ../source4/smbd/service.c:63
#78 0x0000000801753f76 in server_service_startup (event_ctx=0x80d824550, lp_ctx=0x80d83b850, model=0x80d87d040 "standard", server_services=0x80d824350)
#79 0x000000000040c79c in binary_smbd_main (binary_name=0x410402 "samba", argc=6, argv=0x7fffffff9750) at ../source4/smbd/server.c:477
#80 0x000000000040c882 in main (argc=6, argv=0x7fffffff9750) at ../source4/smbd/server.c:497

My impression is that we are looping due to the
non-blocking optimization in tsocket_bsd.c:845. The kernel
gives us "0 bytes available" as per FIONREAD, and we then
successfully recvfrom those 0 bytes from the socket. And as
this is not a valid DNS/KRB/CLDAP/... packet, we enter that
loop immediately again. Maybe we should re-think the
handling of "0" bytes available in
tdgram_bsd_recvfrom_handler.

With best regards,

Volker Lendecke

-- 
SerNet GmbH, Bahnhofsallee 1b, 37081 Göttingen
phone: +49-551-370000-0, fax: +49-551-370000-9
AG Göttingen, HRB 2816, GF: Dr. Johannes Loxen
http://www.sernet.de, mailto:kontakt at sernet.de