From patchwork Sun Jun 7 13:34:39 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 8bit X-Patchwork-Submitter: =?utf-8?q?Przemys=C5=82aw_Fierek?= X-Patchwork-Id: 196919 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-5.2 required=3.0 tests=DKIM_SIGNED,DKIM_VALID, HEADER_FROM_DIFFERENT_DOMAINS, INCLUDES_PATCH, MAILING_LIST_MULTI, SPF_HELO_NONE, SPF_PASS, USER_AGENT_SANE_1 autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id DBA70C433E0 for ; Sun, 7 Jun 2020 13:34:47 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 82D5F20723 for ; Sun, 7 Jun 2020 13:34:47 +0000 (UTC) Authentication-Results: mail.kernel.org; dkim=pass (2048-bit key) header.d=silvair-com.20150623.gappssmtp.com header.i=@silvair-com.20150623.gappssmtp.com header.b="oO74wrIG" Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1726536AbgFGNeq (ORCPT ); Sun, 7 Jun 2020 09:34:46 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:34984 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1726522AbgFGNep (ORCPT ); Sun, 7 Jun 2020 09:34:45 -0400 Received: from mail-lj1-x22c.google.com (mail-lj1-x22c.google.com [IPv6:2a00:1450:4864:20::22c]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id E2E59C08C5C2 for ; Sun, 7 Jun 2020 06:34:44 -0700 (PDT) Received: by mail-lj1-x22c.google.com with SMTP id x18so718196lji.1 for ; Sun, 07 Jun 2020 06:34:44 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=silvair-com.20150623.gappssmtp.com; s=20150623; h=from:subject:to:cc:message-id:date:user-agent:mime-version :content-language; bh=arPQqpZ4J5CJL7kf1Df1N0NF9F132QxvEUodblLo484=; b=oO74wrIGEUAX9AJKgx4mg8NPP55SgF9DZXlhg3sHq8rsLr0hWtQJb3ODVBGw8vQrSU Hf62ydACVFfgeFsrdBItBiCobBTjbNPGzZSMpnHXeh/nC7pe+3qI+Bkb63E4BfchMGj9 CQ3EjhsviZ//NR9krerNkMs5c1eAsQPBWum7XILKHRwy/wJbHNPdU9JPc5lQmtD39xPI clpWhgYJN9Q07ANIiV/AKu9VOb1m+PctnPiqTedElRF4N0ntMXNa+oi7CHN/TDKeI/9q ZsTcW9yuahK+6nbsbfhbbPNUQDnKpDDsb+GEnVPd5SUxlmmrRXR9Fbe3kBGZoUACGWoR XDPg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:subject:to:cc:message-id:date:user-agent :mime-version:content-language; bh=arPQqpZ4J5CJL7kf1Df1N0NF9F132QxvEUodblLo484=; b=skVaWGxswAY4aCyX8Az3srZBgLYfGcpBhQOSxWBwRDeolqo9GNWVxDsLT05o2CPzl8 inE5mhxStRCt4MXdfbjkbG//2M3rpO/+vFvsWrJPyG1xSjWoYahxMPwg6pRgIYxnt6/P CcylLGOREu9g0+mBIQjfG4ioyQW5HpBdBXQ38bUrLw4vpOd+bFDI30/RJ66NA86lMmp4 oEfezLVITecQKfN6DVuyhWoEGqZEOpLdkUnOvC76zO9kX2kEHQ8678i4gv0O7O49PLQ5 uKL2TDWgXE9AKzNGxkKZcNKFix8RJDY89r9c9x8ad9/vqyGAE2M1r3sk9xeaMKwbLOFO nKVQ== X-Gm-Message-State: AOAM531H35bT35nJgl98njd1FgHxQ0XL3p+GoZgesJAYg/LwvFCAxxhA UOvwrTPfswnrlgse2pYcRjbhyvgkFUo= X-Google-Smtp-Source: ABdhPJwMo1FpTVVgP4O3yLvtBQa72CnSp3tJsVZBjVkX4hTRInALct+WrCdgnr/gLD73yxytI9bkIQ== X-Received: by 2002:a2e:8e27:: with SMTP id r7mr8802102ljk.382.1591536881465; Sun, 07 Jun 2020 06:34:41 -0700 (PDT) Received: from [192.168.65.55] (174.60.citypartner.pl. [195.210.60.174]) by smtp.gmail.com with ESMTPSA id u9sm3373831ljd.9.2020.06.07.06.34.40 (version=TLS1_3 cipher=TLS_AES_128_GCM_SHA256 bits=128/128); Sun, 07 Jun 2020 06:34:40 -0700 (PDT) From: =?utf-8?q?Przemys=C5=82aw_Fierek?= Subject: Segmentation fault in the mesh/node.c To: Brian Gix Cc: inga.stotland@intel.com, linux-bluetooth@vger.kernel.org Message-ID: <116e6cc1-5a49-a833-689b-4f00880e455b@silvair.com> Date: Sun, 7 Jun 2020 15:34:39 +0200 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:68.0) Gecko/20100101 Thunderbird/68.8.0 MIME-Version: 1.0 Content-Language: en-US Sender: linux-bluetooth-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-bluetooth@vger.kernel.org Hi, After rebase on the latest BlueZ version our functional tests failed on SEGV in the `node.c` file. Seems that call two D-Bus functions `join` and `leave` one after the other (before receive `join_complete`) causes SEGV. In the attached files there is the backtrace and the diff with my changes (adds extra some logs). Best regards, Przemysław Fierek 11:58:15 =================================== FAILURES =================================== 11:58:15 _______________________ test_remove_storage_after_leave ________________________ 11:58:15 11:58:15 application = ._Application object at 0x7f0cf3fb1050> 11:58:15 meshd = 11:58:15 node_storage = .NodeStorage'> 11:58:15 11:58:15 async def test_remove_storage_after_leave(application, meshd, node_storage): 11:58:15 await application.import_node() 11:58:15 11:58:15 assert application.token_ring.token 11:58:15 11:58:15 with node_storage() as storage, node_storage(backup=True) as backup: 11:58:15 assert storage["token"] == application.token_ring.token 11:58:15 assert backup["token"] == application.token_ring.token 11:58:15 11:58:15 > await application.leave() 11:58:15 11:58:15 bluez_tests/test_storage.py:230: 11:58:15 _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 11:58:15 /usr/local/lib/python3.7/dist-packages/bluetooth_mesh/application.py:721: in leave 11:58:15 await self.network_interface.leave(self.token_ring.token) 11:58:15 /usr/local/lib/python3.7/dist-packages/bluetooth_mesh/interfaces.py:309: in leave 11:58:15 await self._interface.call_leave(token) 11:58:15 /usr/local/lib/python3.7/dist-packages/dbus_next/aio/proxy_object.py:79: in method_fn 11:58:15 BaseProxyInterface._check_method_return(msg, intr_method.out_signature) 11:58:15 _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 11:58:15 11:58:15 msg = , signature = '' 11:58:15 11:58:15 @staticmethod 11:58:15 def _check_method_return(msg, signature=None): 11:58:15 if msg.message_type == MessageType.ERROR: 11:58:15 > raise DBusError._from_message(msg) 11:58:15 E dbus_next.errors.DBusError: Message recipient disconnected from message bus without replying 11:58:15 11:58:15 /usr/local/lib/python3.7/dist-packages/dbus_next/proxy_object.py:59: DBusError 11:58:15 ------------------------------ Captured log setup ------------------------------ 11:58:15 09:58:06.319 asyncio DEBUG Using selector: EpollSelector 11:58:15 09:58:06.393 MESHD INFO Starting: ['gosu', 'root', 'env', 'SEGFAULT_SIGNALS=abrt segv fpe', 'LD_PRELOAD=/lib/x86_64-linux-gnu/libSegFault.so', '/usr/libexec/bluetooth/bluetooth-meshd', '--config=/tmp/pytest-of-user/pytest-0/test_remove_storage_after_leav0/config', '--io=tcpserver:65254', '--debug'] 11:58:15 09:58:06.402 MESHD.stderr INFO 2020-06-05 09:58:06.399 main.c:126 ready_callback D-Bus ready 11:58:15 09:58:06.402 MESHD.stderr INFO 2020-06-05 09:58:06.399 main.c:107 request_name_callback Request name success 11:58:15 09:58:06.402 MESHD.stderr INFO 2020-06-05 09:58:06.399 mesh.c:276 mesh_init Loading node configuration from /tmp/pytest-of-user/pytest-0/test_remove_storage_after_leav0/config 11:58:15 09:58:06.403 MESHD INFO Started 11:58:15 09:58:06.406 APPLICATION INFO Elements: {} 11:58:15 09:58:06.407 APPLICATION DEBUG Connecting to D-Bus 11:58:15 09:58:06.409 MESHD.stderr INFO 2020-06-05 09:58:06.403 mesh-io-tcpserver.c:435 tls_ctx_init TLS initialization: done 11:58:15 09:58:06.409 MESHD.stderr INFO 2020-06-05 09:58:06.403 mesh-io-tcpserver.c:234 get_fd_info Server bind -> addr:0.0.0.0 port:65254 fd:6 11:58:15 09:58:06.409 MESHD.stderr INFO 2020-06-05 09:58:06.403 mesh-io-tcpserver.c:580 tcpserver_io_init Started mesh on tcp port 65254 11:58:15 09:58:06.409 MESHD.stderr INFO 2020-06-05 09:58:06.403 mesh.c:296 mesh_init mesh/mesh.c:mesh_init() io 0x56413d49e9c0 11:58:15 09:58:06.410 MESHD.stderr INFO 2020-06-05 09:58:06.404 mesh.c:881 mesh_dbus_init Added Network Interface on /org/bluez/mesh 11:58:15 09:58:06.418 APPLICATION INFO Connecting to org.bluez.mesh 11:58:15 09:58:06.425 APPLICATION INFO Registering application 11:58:15 ------------------------------ Captured log call ------------------------------- 11:58:15 09:58:06.434 APPLICATION WARNING Import 83bf3b46-8103-45a2-8bcc-e70d8d0b46d3 11:58:15 09:58:06.436 MESHD.stderr INFO 2020-06-05 09:58:06.435 mesh.c:778 import_call mesh/mesh.c:import_call() Import local node request 11:58:15 09:58:06.437 MESHD.stderr INFO 2020-06-05 09:58:06.435 node.c:1720 node_import mesh/node.c:node_import() 11:58:15 09:58:06.437 MESHD.stderr INFO 2020-06-05 09:58:06.435 node.c:267 node_new new elements: 0x56413d4ca930 11:58:15 09:58:06.438 MESHD.stderr INFO 2020-06-05 09:58:06.438 node.c:1283 get_app_properties mesh/node.c:get_app_properties() path /com/silvair/application 11:58:15 09:58:06.438 MESHD.stderr INFO 2020-06-05 09:58:06.438 node.c:1129 get_element_properties mesh/node.c:get_element_properties() path /com/silvair/application/element0 11:58:15 09:58:06.439 MESHD.stderr INFO 2020-06-05 09:58:06.438 node.c:1214 convert_node_to_storage db_node->elements 0x56413d4c9840 11:58:15 09:58:06.440 MESHD.stderr INFO 2020-06-05 09:58:06.438 mesh-config-json.c:1706 mesh_config_create mesh/mesh-config-json.c:mesh_config_create() New node config /tmp/pytest-of-user/pytest-0/test_remove_storage_after_leav0/config/83bf3b46810345a28bcce70d8d0b46d3/node.json 11:58:15 09:58:06.450 MESHD.stderr INFO 2020-06-05 09:58:06.450 net-keys.c:493 net_key_beacon_refresh mesh/net-keys.c:net_key_beacon_refresh() Setting SNB: IVI: 00000000, IVU: 0, KR: 0 11:58:15 09:58:06.451 MESHD.stderr INFO 2020-06-05 09:58:06.450 util.c:52 print_packet mesh/util.c:print_packet() 51086.450 Set SNB Beacon to: 2b01003ecaff672f67337000000000a502cffc80248d4c 11:58:15 09:58:06.451 MESHD.stderr INFO 2020-06-05 09:58:06.450 mesh-config-json.c:565 mesh_config_net_key_add mesh/mesh-config-json.c:mesh_config_net_key_add() netKey 0000 11:58:15 09:58:06.451 MESHD.stderr INFO 2020-06-05 09:58:06.451 net.c:778 mesh_net_set_friend_mode mesh/net.c:mesh_net_set_friend_mode() mesh_net_set_friend_mode - 0 11:58:15 09:58:06.452 MESHD.stderr INFO 2020-06-05 09:58:06.451 net.c:292 trigger_heartbeat mesh/net.c:trigger_heartbeat() trigger_heartbeat: 0001 --> 0 11:58:15 09:58:06.453 MESHD.stderr INFO 2020-06-05 09:58:06.453 cfgmod-server.c:1263 cfgmod_server_init mesh/cfgmod-server.c:cfgmod_server_init() 00 11:58:15 09:58:06.454 MESHD.stderr INFO 2020-06-05 09:58:06.453 mesh.c:712 create_node_ready_cb mesh/mesh.c:create_node_ready_cb() Calling JoinComplete (create) 11:58:15 09:58:06.461 STORAGE INFO /tmp/pytest-of-user/pytest-0/test_remove_storage_after_leav0/config/83bf3b46810345a28bcce70d8d0b46d3/node.json 11:58:15 09:58:06.468 STORAGE INFO /tmp/pytest-of-user/pytest-0/test_remove_storage_after_leav0/config/83bf3b46810345a28bcce70d8d0b46d3/node.json.bak 11:58:15 09:58:06.474 APPLICATION INFO Leave 11:58:15 09:58:06.475 MESHD.stderr INFO 2020-06-05 09:58:06.475 mesh.c:659 leave_call mesh/mesh.c:leave_call() Leave 11:58:15 09:58:06.475 MESHD.stderr INFO 2020-06-05 09:58:06.475 mesh-config-json.c:2329 mesh_config_destroy_nvm mesh/mesh-config-json.c:mesh_config_destroy_nvm() Delete node config /tmp/pytest-of-user/pytest-0/test_remove_storage_after_leav0/config/83bf3b46810345a28bcce70d8d0b46d3 11:58:15 09:58:06.476 MESHD.stderr INFO 2020-06-05 09:58:06.476 util.c:151 del_fobject mesh/util.c:del_fobject() RM /tmp/pytest-of-user/pytest-0/test_remove_storage_after_leav0/config/83bf3b46810345a28bcce70d8d0b46d3/node.json.bak 11:58:15 09:58:06.477 MESHD.stderr INFO 2020-06-05 09:58:06.476 util.c:151 del_fobject mesh/util.c:del_fobject() RM /tmp/pytest-of-user/pytest-0/test_remove_storage_after_leav0/config/83bf3b46810345a28bcce70d8d0b46d3/node.json 11:58:15 09:58:06.477 MESHD.stderr INFO 2020-06-05 09:58:06.476 util.c:145 del_fobject mesh/util.c:del_fobject() RMDIR /tmp/pytest-of-user/pytest-0/test_remove_storage_after_leav0/config/83bf3b46810345a28bcce70d8d0b46d3 11:58:15 09:58:06.477 MESHD.stderr INFO 2020-06-05 09:58:06.476 node.c:296 free_node_dbus_resources Node: 0x56413d4cadb0 11:58:15 09:58:06.477 MESHD.stderr INFO 2020-06-05 09:58:06.476 node.c:306 free_node_dbus_resources elements: 0x56413d4ca930 11:58:15 09:58:06.478 MESHD.stderr INFO 2020-06-05 09:58:06.476 node.c:278 free_element_path el: 0x56413d49f3d0, path: 0x56413d4cac50 11:58:15 09:58:06.478 MESHD.stderr INFO 2020-06-05 09:58:06.476 node.c:343 free_node_resources log1 11:58:15 09:58:06.478 MESHD.stderr INFO 2020-06-05 09:58:06.476 node.c:345 free_node_resources log2 11:58:15 09:58:06.479 MESHD.stderr INFO 2020-06-05 09:58:06.476 node.c:347 free_node_resources log3 11:58:15 09:58:06.479 MESHD.stderr INFO 2020-06-05 09:58:06.477 node.c:353 free_node_resources log4 11:58:15 09:58:06.479 MESHD.stderr INFO 2020-06-05 09:58:06.477 node.c:2414 node_finalize_new_node Nnnnode: 0x56413d4cadb0 11:58:15 09:58:06.479 MESHD.stderr INFO 2020-06-05 09:58:06.477 node.c:296 free_node_dbus_resources Node: 0x56413d4cadb0 11:58:15 09:58:06.480 MESHD.stderr INFO 2020-06-05 09:58:06.477 node.c:306 free_node_dbus_resources elements: 0x56413d498010 11:58:15 09:58:06.480 MESHD.segfault INFO *** Segmentation fault 11:58:15 09:58:06.480 MESHD.registers DEBUG Register dump: 11:58:15 09:58:06.480 MESHD.registers DEBUG 11:58:15 09:58:06.481 MESHD.registers DEBUG RAX: 0000000000000000 RBX: 0005000600070007 RCX: 0000000000000000 11:58:15 09:58:06.481 MESHD.registers DEBUG RDX: 0000000000000000 RSI: 000056413c31ba70 RDI: 000056413d498010 11:58:15 09:58:06.481 MESHD.registers DEBUG RBP: 000056413c31ba70 R8 : 0000000000000019 R9 : 0000000000000019 11:58:15 09:58:06.481 MESHD.registers DEBUG R10: 000056413c37a2ae R11: 0000000000000246 R12: 0000000000000000 11:58:15 09:58:06.482 MESHD.registers DEBUG R13: 000056413d4cdf20 R14: 000056413d49e1a0 R15: 0000000000000001 11:58:15 09:58:06.482 MESHD.registers DEBUG RSP: 00007ffc556d92b0 11:58:15 09:58:06.482 MESHD.registers DEBUG 11:58:15 09:58:06.482 MESHD.registers DEBUG RIP: 000056413c347330 EFLAGS: 00010202 11:58:15 09:58:06.483 MESHD.registers DEBUG 11:58:15 09:58:06.483 MESHD.registers DEBUG CS: 0033 FS: 0000 GS: 0000 11:58:15 09:58:06.483 MESHD.registers DEBUG 11:58:15 09:58:06.483 MESHD.registers DEBUG Trap: 0000000d Error: 00000000 OldMask: 00004002 CR2: 00000000 11:58:15 09:58:06.484 MESHD.registers DEBUG 11:58:15 09:58:06.484 MESHD.registers DEBUG FPUCW: 0000037f FPUSW: 00000000 TAG: 00000000 11:58:15 09:58:06.484 MESHD.registers DEBUG RIP: 00000000 RDP: 00000000 11:58:15 09:58:06.484 MESHD.registers DEBUG 11:58:15 09:58:06.485 MESHD.registers DEBUG ST(0) 0000 0000000000000000 ST(1) 0000 0000000000000000 11:58:15 09:58:06.485 MESHD.registers DEBUG ST(2) 0000 0000000000000000 ST(3) 0000 0000000000000000 11:58:15 09:58:06.485 MESHD.registers DEBUG ST(4) 0000 0000000000000000 ST(5) 0000 0000000000000000 11:58:15 09:58:06.485 MESHD.registers DEBUG ST(6) 0000 0000000000000000 ST(7) 0000 0000000000000000 11:58:15 09:58:06.486 MESHD.registers DEBUG mxcsr: 1f80 11:58:15 09:58:06.486 MESHD.registers DEBUG XMM0: 00000000000000000000000000ffff00 XMM1: 00000000000000000000000000ffff00 11:58:15 09:58:06.486 MESHD.registers DEBUG XMM2: 00000000000000000000000000ffff00 XMM3: 00000000000000000000000000ffff00 11:58:15 09:58:06.486 MESHD.registers DEBUG XMM4: 00000000000000000000000000ffff00 XMM5: 00000000000000000000000000ffff00 11:58:15 09:58:06.487 MESHD.registers DEBUG XMM6: 00000000000000000000000000ffff00 XMM7: 00000000000000000000000000ffff00 11:58:15 09:58:06.487 MESHD.registers DEBUG XMM8: 00000000000000000000000000ffff00 XMM9: 00000000000000000000000000ffff00 11:58:15 09:58:06.487 MESHD.registers DEBUG XMM10: 00000000000000000000000000ffff00 XMM11: 00000000000000000000000000ffff00 11:58:15 09:58:06.487 MESHD.registers DEBUG XMM12: 00000000000000000000000000ffff00 XMM13: 00000000000000000000000000ffff00 11:58:15 09:58:06.487 MESHD.registers DEBUG XMM14: 00000000000000000000000000ffff00 XMM15: 00000000000000000000000000ffff00 11:58:15 09:58:06.488 MESHD.registers DEBUG 11:58:15 09:58:06.489 MESHD.backtrace INFO Backtrace: 11:58:15 09:58:06.509 MESHD.backtrace INFO l_queue_foreach /home/user/bluez/ell/queue.c:441 (discriminator 3) 11:58:15 09:58:06.510 MESHD.backtrace DEBUG 439: 11:58:15 09:58:06.510 MESHD.backtrace DEBUG 440: for (entry = queue->head; entry; entry = entry->next) 11:58:15 09:58:06.511 MESHD.backtrace DEBUG 441: function(entry->data, user_data); 👈 😡 11:58:15 09:58:06.511 MESHD.backtrace DEBUG 442: } 11:58:15 09:58:06.511 MESHD.backtrace DEBUG 443: 11:58:15 09:58:06.511 MESHD.backtrace DEBUG 444: /** 11:58:15 09:58:06.512 MESHD.backtrace DEBUG 11:58:15 09:58:06.525 MESHD.backtrace INFO free_node_dbus_resources /home/user/bluez/mesh/node.c:309 11:58:15 09:58:06.526 MESHD.backtrace DEBUG 307: 11:58:15 09:58:06.526 MESHD.backtrace DEBUG 308: l_queue_foreach(node->elements, free_element_path, NULL); 11:58:15 09:58:06.527 MESHD.backtrace DEBUG 309: l_free(node->owner); 👈 😡 11:58:15 09:58:06.527 MESHD.backtrace DEBUG 310: node->owner = NULL; 11:58:15 09:58:06.527 MESHD.backtrace DEBUG 311: l_free(node->app_path); 11:58:15 09:58:06.527 MESHD.backtrace DEBUG 312: node->app_path = NULL; 11:58:15 09:58:06.528 MESHD.backtrace DEBUG 11:58:15 09:58:06.543 MESHD.backtrace INFO node_finalize_new_node /home/user/bluez/mesh/node.c:2417 11:58:15 09:58:06.544 MESHD.backtrace DEBUG 2415: 11:58:15 09:58:06.545 MESHD.backtrace DEBUG 2416: free_node_dbus_resources(node); 11:58:15 09:58:06.545 MESHD.backtrace DEBUG 2417: mesh_agent_remove(node->agent); 👈 😡 11:58:15 09:58:06.545 MESHD.backtrace DEBUG 2418: 11:58:15 09:58:06.545 MESHD.backtrace DEBUG 2419: /* Register callback for the node's io */ 11:58:15 09:58:06.546 MESHD.backtrace DEBUG 2420: attach_io(node, io); 11:58:15 09:58:06.546 MESHD.backtrace DEBUG 11:58:15 09:58:06.560 MESHD.backtrace INFO create_join_complete_reply_cb /home/user/bluez/mesh/mesh.c:679 11:58:15 09:58:06.561 MESHD.backtrace DEBUG 677: } 11:58:15 09:58:06.561 MESHD.backtrace DEBUG 678: 11:58:15 09:58:06.561 MESHD.backtrace DEBUG 679: node_finalize_new_node(node, mesh.io); 👈 😡 11:58:15 09:58:06.561 MESHD.backtrace DEBUG 680: } 11:58:15 09:58:06.561 MESHD.backtrace DEBUG 681: 11:58:15 09:58:06.562 MESHD.backtrace DEBUG 682: static void create_node_ready_cb(void *user_data, int status, 11:58:15 09:58:06.562 MESHD.backtrace DEBUG 11:58:15 09:58:06.572 MESHD.backtrace INFO send_reply /home/user/bluez/mesh/dbus.c:161 11:58:15 09:58:06.573 MESHD.backtrace DEBUG 159: l_timeout_remove(info->timeout); 11:58:15 09:58:06.573 MESHD.backtrace DEBUG 160: info->cb(message, info->user_data); 11:58:15 09:58:06.574 MESHD.backtrace DEBUG 161: l_free(info); 👈 😡 11:58:15 09:58:06.574 MESHD.backtrace DEBUG 162: } 11:58:15 09:58:06.574 MESHD.backtrace DEBUG 163: 11:58:15 09:58:06.574 MESHD.backtrace DEBUG 164: static void send_timeout(struct l_timeout *timeout, void *user_data) 11:58:15 09:58:06.575 MESHD.backtrace DEBUG 11:58:15 09:58:06.587 MESHD.backtrace INFO handle_method_return /home/user/bluez/ell/dbus.c:216 11:58:15 09:58:06.588 MESHD.backtrace DEBUG 214: 11:58:15 09:58:06.588 MESHD.backtrace DEBUG 215: if (callback->callback) 11:58:15 09:58:06.589 MESHD.backtrace DEBUG 216: callback->callback(message, callback->user_data); 👈 😡 11:58:15 09:58:06.589 MESHD.backtrace DEBUG 217: 11:58:15 09:58:06.589 MESHD.backtrace DEBUG 218: message_queue_destroy(callback); 11:58:15 09:58:06.589 MESHD.backtrace DEBUG 219: } 11:58:15 09:58:06.590 MESHD.backtrace DEBUG 11:58:15 09:58:06.601 MESHD.backtrace INFO io_callback /home/user/bluez/ell/io.c:126 11:58:15 09:58:06.602 MESHD.backtrace DEBUG 124: "read event <%p>", io); 11:58:15 09:58:06.602 MESHD.backtrace DEBUG 125: 11:58:15 09:58:06.603 MESHD.backtrace DEBUG 126: if (!io->read_handler(io, io->read_data)) { 👈 😡 11:58:15 09:58:06.603 MESHD.backtrace DEBUG 127: if (io->read_destroy) 11:58:15 09:58:06.603 MESHD.backtrace DEBUG 128: io->read_destroy(io->read_data); 11:58:15 09:58:06.603 MESHD.backtrace DEBUG 129: 11:58:15 09:58:06.604 MESHD.backtrace DEBUG 11:58:15 09:58:06.618 MESHD.backtrace INFO l_main_iterate /home/user/bluez/ell/main.c:467 11:58:15 09:58:06.619 MESHD.backtrace DEBUG 465: } 11:58:15 09:58:06.619 MESHD.backtrace DEBUG 466: 11:58:15 09:58:06.619 MESHD.backtrace DEBUG 467: for (n = 0; n < nfds; n++) { 👈 😡 11:58:15 09:58:06.620 MESHD.backtrace DEBUG 468: data = events[n].data.ptr; 11:58:15 09:58:06.620 MESHD.backtrace DEBUG 469: 11:58:15 09:58:06.620 MESHD.backtrace DEBUG 470: if (data->flags & WATCH_FLAG_DESTROYED) 11:58:15 09:58:06.620 MESHD.backtrace DEBUG 11:58:15 09:58:06.635 MESHD.backtrace INFO l_main_run /home/user/bluez/ell/main.c:516 11:58:15 09:58:06.636 MESHD.backtrace DEBUG 514: 11:58:15 09:58:06.637 MESHD.backtrace DEBUG 515: for (;;) { 11:58:15 09:58:06.637 MESHD.backtrace DEBUG 516: if (epoll_terminate) 👈 😡 11:58:15 09:58:06.638 MESHD.backtrace DEBUG 517: break; 11:58:15 09:58:06.639 MESHD.backtrace DEBUG 518: 11:58:15 09:58:06.639 MESHD.backtrace DEBUG 519: timeout = l_main_prepare(); 11:58:15 09:58:06.639 MESHD.backtrace DEBUG 11:58:15 09:58:06.656 MESHD.backtrace INFO l_main_run_with_signal /home/user/bluez/ell/main.c:644 11:58:15 09:58:06.657 MESHD.backtrace DEBUG 642: result = l_main_run(); 11:58:15 09:58:06.657 MESHD.backtrace DEBUG 643: 11:58:15 09:58:06.657 MESHD.backtrace DEBUG 644: l_signal_remove(sigint); 👈 😡 11:58:15 09:58:06.658 MESHD.backtrace DEBUG 645: l_signal_remove(sigterm); 11:58:15 09:58:06.658 MESHD.backtrace DEBUG 646: 11:58:15 09:58:06.658 MESHD.backtrace DEBUG 647: l_free(data); 11:58:15 09:58:06.659 MESHD.backtrace DEBUG 11:58:15 09:58:06.680 MESHD.backtrace INFO main /home/user/bluez/mesh/main.c:303 11:58:15 09:58:06.681 MESHD.backtrace DEBUG 301: } 11:58:15 09:58:06.681 MESHD.backtrace DEBUG 302: 11:58:15 09:58:06.682 MESHD.backtrace DEBUG 303: status = l_main_run_with_signal(signal_handler, NULL); 👈 😡 11:58:15 09:58:06.682 MESHD.backtrace DEBUG 304: 11:58:15 09:58:06.683 MESHD.backtrace DEBUG 305: done: 11:58:15 09:58:06.683 MESHD.backtrace DEBUG 306: if (io) 11:58:15 09:58:06.683 MESHD.backtrace DEBUG 11:58:15 09:58:06.700 MESHD.backtrace INFO /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf3)[0x7f01065241e3] 11:58:15 09:58:06.721 MESHD.backtrace INFO _start /usr/libexec/bluetooth/bluetooth-meshd(+0x2b69e)[0x56413c30069e] 11:58:15 09:58:06.722 MESHD.backtrace INFO 11:58:15 09:58:06.723 MESHD.memory DEBUG Memory map: 11:58:15 09:58:06.723 MESHD.memory DEBUG 11:58:15 09:58:06.724 MESHD.memory DEBUG 56413c2d5000-56413c2fe000 r--p 00000000 00:64 3174 /usr/libexec/bluetooth/bluetooth-meshd 11:58:15 09:58:06.724 MESHD.memory DEBUG 56413c2fe000-56413c377000 r-xp 00029000 00:64 3174 /usr/libexec/bluetooth/bluetooth-meshd 11:58:15 09:58:06.725 MESHD.memory DEBUG 56413c377000-56413c39a000 r--p 000a2000 00:64 3174 /usr/libexec/bluetooth/bluetooth-meshd 11:58:15 09:58:06.725 MESHD.memory DEBUG 56413c39b000-56413c39f000 r--p 000c5000 00:64 3174 /usr/libexec/bluetooth/bluetooth-meshd 11:58:15 09:58:06.725 MESHD.memory DEBUG 56413c39f000-56413c3bf000 rw-p 000c9000 00:64 3174 /usr/libexec/bluetooth/bluetooth-meshd 11:58:15 09:58:06.726 MESHD.memory DEBUG 56413c3bf000-56413c3df000 rw-p 00000000 00:00 0 11:58:15 09:58:06.726 MESHD.memory DEBUG 56413d498000-56413d4da000 rw-p 00000000 00:00 0 [heap] 11:58:15 09:58:06.726 MESHD.memory DEBUG 7f01064b5000-7f01064b8000 r--p 00000000 00:64 5779 /usr/lib/x86_64-linux-gnu/libgcc_s.so.1 11:58:15 09:58:06.727 MESHD.memory DEBUG 7f01064b8000-7f01064c9000 r-xp 00003000 00:64 5779 /usr/lib/x86_64-linux-gnu/libgcc_s.so.1 11:58:15 09:58:06.727 MESHD.memory DEBUG 7f01064c9000-7f01064cd000 r--p 00014000 00:64 5779 /usr/lib/x86_64-linux-gnu/libgcc_s.so.1 11:58:15 09:58:06.727 MESHD.memory DEBUG 7f01064cd000-7f01064ce000 r--p 00017000 00:64 5779 /usr/lib/x86_64-linux-gnu/libgcc_s.so.1 11:58:15 09:58:06.728 MESHD.memory DEBUG 7f01064ce000-7f01064cf000 rw-p 00018000 00:64 5779 /usr/lib/x86_64-linux-gnu/libgcc_s.so.1 11:58:15 09:58:06.728 MESHD.memory DEBUG 7f01064cf000-7f01064d2000 rw-p 00000000 00:00 0 11:58:15 09:58:06.728 MESHD.memory DEBUG 7f01064d2000-7f01064d3000 r--p 00000000 00:64 52 /usr/lib/x86_64-linux-gnu/libdl-2.30.so 11:58:15 09:58:06.729 MESHD.memory DEBUG 7f01064d3000-7f01064d5000 r-xp 00001000 00:64 52 /usr/lib/x86_64-linux-gnu/libdl-2.30.so 11:58:15 09:58:06.729 MESHD.memory DEBUG 7f01064d5000-7f01064d6000 r--p 00003000 00:64 52 /usr/lib/x86_64-linux-gnu/libdl-2.30.so 11:58:15 09:58:06.730 MESHD.memory DEBUG 7f01064d6000-7f01064d7000 r--p 00003000 00:64 52 /usr/lib/x86_64-linux-gnu/libdl-2.30.so 11:58:15 09:58:06.730 MESHD.memory DEBUG 7f01064d7000-7f01064d8000 rw-p 00004000 00:64 52 /usr/lib/x86_64-linux-gnu/libdl-2.30.so 11:58:15 09:58:06.730 MESHD.memory DEBUG 7f01064d8000-7f01064da000 rw-p 00000000 00:00 0 11:58:15 09:58:06.731 MESHD.memory DEBUG 7f01064da000-7f01064e1000 r--p 00000000 00:64 77 /usr/lib/x86_64-linux-gnu/libpthread-2.30.so 11:58:15 09:58:06.731 MESHD.memory DEBUG 7f01064e1000-7f01064f2000 r-xp 00007000 00:64 77 /usr/lib/x86_64-linux-gnu/libpthread-2.30.so 11:58:15 09:58:06.731 MESHD.memory DEBUG 7f01064f2000-7f01064f7000 r--p 00018000 00:64 77 /usr/lib/x86_64-linux-gnu/libpthread-2.30.so 11:58:15 09:58:06.732 MESHD.memory DEBUG 7f01064f7000-7f01064f8000 r--p 0001c000 00:64 77 /usr/lib/x86_64-linux-gnu/libpthread-2.30.so 11:58:15 09:58:06.732 MESHD.memory DEBUG 7f01064f8000-7f01064f9000 rw-p 0001d000 00:64 77 /usr/lib/x86_64-linux-gnu/libpthread-2.30.so 11:58:15 09:58:06.732 MESHD.memory DEBUG 7f01064f9000-7f01064fd000 rw-p 00000000 00:00 0 11:58:15 09:58:06.733 MESHD.memory DEBUG 7f01064fd000-7f0106522000 r--p 00000000 00:64 42 /usr/lib/x86_64-linux-gnu/libc-2.30.so 11:58:15 09:58:06.733 MESHD.memory DEBUG 7f0106522000-7f010669a000 r-xp 00025000 00:64 42 /usr/lib/x86_64-linux-gnu/libc-2.30.so 11:58:15 09:58:06.733 MESHD.memory DEBUG 7f010669a000-7f01066e4000 r--p 0019d000 00:64 42 /usr/lib/x86_64-linux-gnu/libc-2.30.so 11:58:15 09:58:06.734 MESHD.memory DEBUG 7f01066e4000-7f01066e7000 r--p 001e6000 00:64 42 /usr/lib/x86_64-linux-gnu/libc-2.30.so 11:58:15 09:58:06.734 MESHD.memory DEBUG 7f01066e7000-7f01066ea000 rw-p 001e9000 00:64 42 /usr/lib/x86_64-linux-gnu/libc-2.30.so 11:58:15 09:58:06.735 MESHD.memory DEBUG 7f01066ea000-7f01066ee000 rw-p 00000000 00:00 0 11:58:15 09:58:06.735 MESHD.memory DEBUG 7f01066ee000-7f0106766000 r--p 00000000 00:64 3952 /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1 11:58:15 09:58:06.735 MESHD.memory DEBUG 7f0106766000-7f0106904000 r-xp 00078000 00:64 3952 /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1 11:58:15 09:58:06.736 MESHD.memory DEBUG 7f0106904000-7f0106992000 r--p 00216000 00:64 3952 /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1 11:58:15 09:58:06.736 MESHD.memory DEBUG 7f0106992000-7f01069be000 r--p 002a3000 00:64 3952 /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1 11:58:15 09:58:06.736 MESHD.memory DEBUG 7f01069be000-7f01069c0000 rw-p 002cf000 00:64 3952 /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1 11:58:15 09:58:06.737 MESHD.memory DEBUG 7f01069c0000-7f01069c3000 rw-p 00000000 00:00 0 11:58:15 09:58:06.737 MESHD.memory DEBUG 7f01069c3000-7f01069df000 r--p 00000000 00:64 4542 /usr/lib/x86_64-linux-gnu/libssl.so.1.1 11:58:15 09:58:06.737 MESHD.memory DEBUG 7f01069df000-7f0106a2e000 r-xp 0001c000 00:64 4542 /usr/lib/x86_64-linux-gnu/libssl.so.1.1 11:58:15 09:58:06.738 MESHD.memory DEBUG 7f0106a2e000-7f0106a48000 r--p 0006b000 00:64 4542 /usr/lib/x86_64-linux-gnu/libssl.so.1.1 11:58:15 09:58:06.738 MESHD.memory DEBUG 7f0106a48000-7f0106a51000 r--p 00084000 00:64 4542 /usr/lib/x86_64-linux-gnu/libssl.so.1.1 11:58:15 09:58:06.738 MESHD.memory DEBUG 7f0106a51000-7f0106a55000 rw-p 0008d000 00:64 4542 /usr/lib/x86_64-linux-gnu/libssl.so.1.1 11:58:15 09:58:06.739 MESHD.memory DEBUG 7f0106a55000-7f0106a59000 r--p 00000000 00:64 5702 /usr/lib/x86_64-linux-gnu/libjson-c.so.4.0.0 11:58:15 09:58:06.739 MESHD.memory DEBUG 7f0106a59000-7f0106a61000 r-xp 00004000 00:64 5702 /usr/lib/x86_64-linux-gnu/libjson-c.so.4.0.0 11:58:15 09:58:06.739 MESHD.memory DEBUG 7f0106a61000-7f0106a64000 r--p 0000c000 00:64 5702 /usr/lib/x86_64-linux-gnu/libjson-c.so.4.0.0 11:58:15 09:58:06.739 MESHD.memory DEBUG 7f0106a64000-7f0106a65000 ---p 0000f000 00:64 5702 /usr/lib/x86_64-linux-gnu/libjson-c.so.4.0.0 11:58:15 09:58:06.740 MESHD.memory DEBUG 7f0106a65000-7f0106a66000 r--p 0000f000 00:64 5702 /usr/lib/x86_64-linux-gnu/libjson-c.so.4.0.0 11:58:15 09:58:06.740 MESHD.memory DEBUG 7f0106a66000-7f0106a67000 rw-p 00010000 00:64 5702 /usr/lib/x86_64-linux-gnu/libjson-c.so.4.0.0 11:58:15 09:58:06.740 MESHD.memory DEBUG 7f0106a6e000-7f0106a6f000 r--p 00000000 00:64 5700 /usr/lib/x86_64-linux-gnu/libSegFault.so 11:58:15 09:58:06.741 MESHD.memory DEBUG 7f0106a6f000-7f0106a72000 r-xp 00001000 00:64 5700 /usr/lib/x86_64-linux-gnu/libSegFault.so 11:58:15 09:58:06.741 MESHD.memory DEBUG 7f0106a72000-7f0106a73000 r--p 00004000 00:64 5700 /usr/lib/x86_64-linux-gnu/libSegFault.so 11:58:15 09:58:06.741 MESHD.memory DEBUG 7f0106a73000-7f0106a74000 r--p 00004000 00:64 5700 /usr/lib/x86_64-linux-gnu/libSegFault.so 11:58:15 09:58:06.741 MESHD.memory DEBUG 7f0106a74000-7f0106a75000 rw-p 00005000 00:64 5700 /usr/lib/x86_64-linux-gnu/libSegFault.so 11:58:15 09:58:06.742 MESHD.memory DEBUG 7f0106a75000-7f0106a77000 rw-p 00000000 00:00 0 11:58:15 09:58:06.742 MESHD.memory DEBUG 7f0106a77000-7f0106a78000 r--p 00000000 00:64 39 /usr/lib/x86_64-linux-gnu/ld-2.30.so 11:58:15 09:58:06.742 MESHD.memory DEBUG 7f0106a78000-7f0106a9a000 r-xp 00001000 00:64 39 /usr/lib/x86_64-linux-gnu/ld-2.30.so 11:58:15 09:58:06.742 MESHD.memory DEBUG 7f0106a9a000-7f0106aa2000 r--p 00023000 00:64 39 /usr/lib/x86_64-linux-gnu/ld-2.30.so 11:58:15 09:58:06.743 MESHD.memory DEBUG 7f0106aa3000-7f0106aa4000 r--p 0002b000 00:64 39 /usr/lib/x86_64-linux-gnu/ld-2.30.so 11:58:15 09:58:06.743 MESHD.memory DEBUG 7f0106aa4000-7f0106aa5000 rw-p 0002c000 00:64 39 /usr/lib/x86_64-linux-gnu/ld-2.30.so 11:58:15 09:58:06.743 MESHD.memory DEBUG 7f0106aa5000-7f0106aa6000 rw-p 00000000 00:00 0 11:58:15 09:58:06.743 MESHD.memory DEBUG 7ffc556bb000-7ffc556dc000 rw-p 00000000 00:00 0 [stack] 11:58:15 09:58:06.744 MESHD.memory DEBUG 7ffc557e9000-7ffc557ec000 r--p 00000000 00:00 0 [vvar] 11:58:15 09:58:06.744 MESHD.memory DEBUG 7ffc557ec000-7ffc557ee000 r-xp 00000000 00:00 0 [vdso] 11:58:15 09:58:06.744 MESHD.memory DEBUG ffffffffff600000-ffffffffff601000 r-xp 00000000 00:00 0 [vsyscall] 11:58:15 09:58:06.746 APPLICATION ERROR Disconnected from org.bluez.mesh (:1.625) 11:58:15 ---------------------------- Captured log teardown ----------------------------- diff --git a/mesh/node.c b/mesh/node.c index db888d27c..bc7151621 100644 --- a/mesh/node.c +++ b/mesh/node.c @@ -264,6 +264,7 @@ static struct mesh_node *node_new(const uint8_t uuid[16]) node = l_new(struct mesh_node, 1); node->net = mesh_net_new(node); node->elements = l_queue_new(); + l_info("new elements: %p", node->elements); memcpy(node->uuid, uuid, sizeof(node->uuid)); set_defaults(node); @@ -274,8 +275,11 @@ static void free_element_path(void *a, void *b) { struct node_element *element = a; + l_info("el: %p, path: %p", element, element->path); + l_free(element->path); element->path = NULL; + } static void element_free(void *data) @@ -289,6 +293,8 @@ static void element_free(void *data) static void free_node_dbus_resources(struct mesh_node *node) { + l_info("Node: %p", node); + if (!node) return; @@ -297,6 +303,8 @@ static void free_node_dbus_resources(struct mesh_node *node) node->disc_watch = 0; } + l_info("elements: %p", node->elements); + l_queue_foreach(node->elements, free_element_path, NULL); l_free(node->owner); node->owner = NULL; @@ -332,12 +340,17 @@ static void free_node_resources(void *data) /* Free dynamic resources */ free_node_dbus_resources(node); + l_info("log1"); l_queue_destroy(node->elements, element_free); + l_info("log2"); + node->elements = NULL; + l_info("log3"); mesh_agent_remove(node->agent); mesh_config_release(node->cfg); mesh_net_free(node->net); l_free(node->storage_dir); l_free(node); + l_info("log4"); } /* @@ -1198,6 +1211,7 @@ static void convert_node_to_storage(struct mesh_node *node, db_node->seq_number = node->seq_number; db_node->elements = l_queue_new(); + l_info("db_node->elements %p", db_node->elements); entry = l_queue_get_entries(node->elements); @@ -1354,6 +1368,8 @@ static bool add_local_node(struct mesh_node *node, uint16_t unicast, bool kr, update_net_settings(node); + mesh_config_save(node->cfg, true, NULL, NULL); + /* Initialize configuration server model */ cfgmod_server_init(node, PRIMARY_ELE_IDX); @@ -2352,6 +2411,8 @@ void node_finalize_new_node(struct mesh_node *node, struct mesh_io *io) if (!node) return; + l_info("Nnnnode: %p", node); + free_node_dbus_resources(node); mesh_agent_remove(node->agent);