UpdateCTestConfiguration from :/home/ralf/src/dbus-1-cmake-cross-x86-build/DartConfiguration.tcl UpdateCTestConfiguration from :/home/ralf/src/dbus-1-cmake-cross-x86-build/DartConfiguration.tcl Test project /home/ralf/src/dbus-1-cmake-cross-x86-build Constructing a list of tests Done constructing a list of tests Checking test dependency graph... Checking test dependency graph end test 2 Start 2: test-bus 2: Test command: /home/ralf/src/dbus-1-cmake-cross-x86-build/bin/test-bus.exe 2: Environment variables: 2: DBUS_TEST_DAEMON=z:/home/ralf/src/dbus-1-cmake-cross-x86-build/bin/dbus-daemon.exe 2: DBUS_SESSION_BUS_ADDRESS= 2: DBUS_FATAL_WARNINGS=1 2: DBUS_TEST_DATA=z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data 2: DBUS_TEST_HOMEDIR=z:/home/ralf/src/dbus-1-cmake-cross-x86-build/dbus 2: Test timeout computed to be: 9.99988e+06 2: 385: [dbus/dbus-memory.c(262):_dbus_decrement_fail_alloc_counter] TODO: memory allocation testing errors disabled for now 2: 385: [dbus/dbus-socket-set-poll.c(98):_dbus_socket_set_poll_new] new socket set at 002433E0 2: 385: [bus/expirelist.c(105):bus_expire_timeout_set_interval] Enabled an expire timeout with interval 0 2: 385: [bus/expirelist.c(373):bus_expire_list_test] next_interval = 1 2: 385: [bus/expirelist.c(153):do_expiration_with_monotonic_time] Expiring an item 00243568 2: 385: [bus/expirelist.c(380):bus_expire_list_test] next_interval = -1 2: 385: [bus/expirelist.c(387):bus_expire_list_test] next_interval = 1100 2: 385: [dbus/dbus-socket-set-poll.c(68):socket_set_poll_free] freed socket set 002433E0 2: 385: [bus/config-parser.c(3040):process_test_valid_subdir] Skipping non-.conf file basic.d 2: 385: [bus/config-parser.c(3040):process_test_valid_subdir] Skipping non-.conf file session.d 2: 385: [bus/config-parser.c(3050):process_test_valid_subdir] expecting valid 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-config-files/forbidding.conf hnd 00000088 opened 2: 385: [bus/config-parser.c(3040):process_test_valid_subdir] Skipping non-.conf file system.d 2: 385: [bus/config-parser.c(3050):process_test_valid_subdir] expecting valid 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-config-files/system.conf hnd 00000088 opened 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-config-files/system.d/test.conf hnd 0000008C opened 2: 385: [bus/config-parser.c(3050):process_test_valid_subdir] expecting valid 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-config-files/session.conf hnd 00000088 opened 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 1000000000 for limit max_incoming_bytes 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 250000000 for limit max_incoming_unix_fds 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 1000000000 for limit max_outgoing_bytes 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 250000000 for limit max_outgoing_unix_fds 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 1000000000 for limit max_message_size 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 120000 for limit service_start_timeout 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 240000 for limit auth_timeout 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 150000 for limit pending_fd_timeout 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 100000 for limit max_completed_connections 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 10000 for limit max_incomplete_connections 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 100000 for limit max_connections_per_user 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 10000 for limit max_pending_service_starts 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 50000 for limit max_names_per_connection 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 50000 for limit max_match_rules_per_connection 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 50000 for limit max_replies_per_connection 2: 385: [bus/config-parser.c(3050):process_test_valid_subdir] expecting valid 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-config-files/systemd-activation.conf hnd 00000088 opened 2: 385: [bus/config-parser.c(3050):process_test_valid_subdir] expecting valid 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-config-files/multi-user.conf hnd 00000088 opened 2: 385: [bus/config-parser.c(3050):process_test_valid_subdir] expecting valid 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-config-files/check-own-rules.conf hnd 00000088 opened 2: 385: [bus/config-parser.c(3050):process_test_valid_subdir] expecting valid 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-config-files/entities.conf hnd 00000088 opened 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-config-files/basic.d/basic.conf hnd 0000008C opened 2: 385: [bus/config-parser.c(3050):process_test_valid_subdir] expecting valid 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-config-files/incoming-limit.conf hnd 00000088 opened 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 1 for limit max_incoming_bytes 2: 385: [bus/config-parser.c(3050):process_test_valid_subdir] expecting valid 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-config-files/finite-timeout.conf hnd 00000088 opened 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 100 for limit reply_timeout 2: 385: [bus/config-parser.c(3050):process_test_valid_subdir] expecting valid 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-config-files/many-rules.conf hnd 00000088 opened 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-config-files/basic.d/basic.conf hnd 0000008C opened 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 5000 for limit max_incoming_bytes 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 5000 for limit max_outgoing_bytes 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 300 for limit max_message_size 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 5000 for limit service_start_timeout 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 6000 for limit auth_timeout 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 50 for limit max_completed_connections 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 80 for limit max_incomplete_connections 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 64 for limit max_connections_per_user 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 64 for limit max_pending_service_starts 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 256 for limit max_names_per_connection 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 512 for limit max_match_rules_per_connection 2: 385: [bus/config-parser.c(3050):process_test_valid_subdir] expecting valid 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-config-files/basic.conf hnd 00000088 opened 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-config-files/basic.d/basic.conf hnd 0000008C opened 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 5000 for limit max_incoming_bytes 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 5000 for limit max_outgoing_bytes 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 300 for limit max_message_size 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 5000 for limit service_start_timeout 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 6000 for limit auth_timeout 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 50 for limit max_completed_connections 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 80 for limit max_incomplete_connections 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 64 for limit max_connections_per_user 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 64 for limit max_pending_service_starts 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 256 for limit max_names_per_connection 2: 385: [bus/config-parser.c(3050):process_test_valid_subdir] expecting valid 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-config-files/debug-allow-all.conf hnd 00000088 opened 2: 385: [bus/config-parser.c(3050):process_test_valid_subdir] expecting valid 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-config-files/listen-unix-runtime.conf hnd 00000088 opened 2: 385: [bus/config-parser.c(3050):process_test_valid_subdir] expecting valid 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-config-files/debug-allow-all-sha1.conf hnd 00000088 opened 2: 385: [bus/config-parser.c(3050):process_test_valid_subdir] expecting invalid 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/invalid-config-files/badselinux-1.conf hnd 00000088 opened 2: 385: [bus/config-parser.c(3050):process_test_valid_subdir] expecting invalid 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/invalid-config-files/circular-3.conf hnd 00000088 opened 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/invalid-config-files/circular-2.conf hnd 00000088 opened 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/invalid-config-files/circular-3.conf hnd 00000088 opened 2: 385: [bus/config-parser.c(3050):process_test_valid_subdir] expecting invalid 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/invalid-config-files/circular-1.conf hnd 00000088 opened 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/invalid-config-files/circular-1.conf hnd 00000088 opened 2: 385: [bus/config-parser.c(3050):process_test_valid_subdir] expecting invalid 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/invalid-config-files/truncated-file.conf hnd 00000088 opened 2: 385: [bus/config-parser.c(3050):process_test_valid_subdir] expecting invalid 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/invalid-config-files/not-well-formed.conf hnd 00000088 opened 2: 385: [bus/config-parser.c(3050):process_test_valid_subdir] expecting invalid 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/invalid-config-files/circular-2.conf hnd 00000088 opened 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/invalid-config-files/circular-3.conf hnd 00000088 opened 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/invalid-config-files/circular-2.conf hnd 00000088 opened 2: 385: [bus/config-parser.c(3050):process_test_valid_subdir] expecting invalid 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/invalid-config-files/badselinux-2.conf hnd 00000088 opened 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/equiv-config-files/entities/entities-2.conf hnd 0000008C opened 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/equiv-config-files/entities/entities-1.conf hnd 0000008C opened 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/equiv-config-files/entities/basic.d/basic.conf hnd 00000090 opened 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/equiv-config-files/entities/entities-1.conf hnd 0000008C opened 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/equiv-config-files/entities/basic.d/basic.conf hnd 00000090 opened 2: 385: [bus/config-parser.c(3307):all_are_equiv] Skipping non-.conf file basic.d 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/equiv-config-files/basic/basic-1.conf hnd 0000008C opened 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/equiv-config-files/basic/basic.d/basic.conf hnd 00000090 opened 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 5000 for limit max_incoming_bytes 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 5000 for limit max_outgoing_bytes 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 300 for limit max_message_size 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 5000 for limit service_start_timeout 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 6000 for limit auth_timeout 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 50 for limit max_completed_connections 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 80 for limit max_incomplete_connections 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 64 for limit max_connections_per_user 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 64 for limit max_pending_service_starts 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 256 for limit max_names_per_connection 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/equiv-config-files/basic/basic-2.conf hnd 0000008C opened 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/equiv-config-files/basic/basic-1.conf hnd 0000008C opened 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/equiv-config-files/basic/basic.d/basic.conf hnd 00000090 opened 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 5000 for limit max_incoming_bytes 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 5000 for limit max_outgoing_bytes 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 300 for limit max_message_size 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 5000 for limit service_start_timeout 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 6000 for limit auth_timeout 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 50 for limit max_completed_connections 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 80 for limit max_incomplete_connections 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 64 for limit max_connections_per_user 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 64 for limit max_pending_service_starts 2: 385: [bus/config-parser.c(2695):bus_config_parser_content] Loaded value 256 for limit max_names_per_connection 2: 385: [bus/config-parser.c(3307):all_are_equiv] Skipping non-.conf file basic.d 2: 385: [dbus/dbus-internals.c(1043):_dbus_test_oom_handling] Running once to count mallocs 2: 385: [dbus/dbus-internals.c(1051):_dbus_test_oom_handling] 2: ================= 2: parsing match rules: about 0 mallocs total 2: ================= 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 10 with 1 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 9 with 1 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 8 with 1 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 7 with 1 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 6 with 1 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 5 with 1 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 4 with 1 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 3 with 1 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 2 with 1 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 1 with 1 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 0 with 1 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 10 with 2 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 9 with 2 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 8 with 2 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 7 with 2 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 6 with 2 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 5 with 2 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 4 with 2 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 3 with 2 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 2 with 2 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 1 with 2 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 0 with 2 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 10 with 3 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 9 with 3 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 8 with 3 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 7 with 3 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 6 with 3 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 5 with 3 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 4 with 3 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 3 with 3 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 2 with 3 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 1 with 3 failures) 2: === 2: 385: [dbus/dbus-internals.c(1003):run_failing_each_malloc] 2: === 2: parsing match rules: (will fail malloc 0 with 3 failures) 2: === 2: 385: [dbus/dbus-internals.c(1079):_dbus_test_oom_handling] 2: ================= 2: parsing match rules: all iterations passed 2: ================= 2: 385: [bus/dispatch.c(4974):bus_dispatch_sha1_test] Testing SHA1 context 2: 385: [dbus/dbus-dataslot.c(135):_dbus_data_slot_allocator_alloc] Allocated slot 0 on allocator 6DBE4338 total 1 slots allocated 1 used 2: 385: [dbus/dbus-socket-set-poll.c(98):_dbus_socket_set_poll_new] new socket set at 00243588 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-config-files/debug-allow-all-sha1.conf hnd 00000084 opened 2: 385: [dbus/dbus-server.c(165):_dbus_server_init_base] Initialized server on address debug-pipe:name=test-server,guid=dd888b88621788603d4aea185635197a 2: 385: [dbus/dbus-server.c(165):_dbus_server_init_base] Initialized server on address tcp:host=localhost,port=35145,guid=f05ae1e4215be3914c4028015635197a 2: 385: [dbus/dbus-watch.c(318):_dbus_watch_list_set_functions] Adding a read watch on fd 136 using newly-set add watch function 2: 385: [dbus/dbus-socket-set-poll.c(146):socket_set_poll_add] before adding fd 136 to 00243588, 0 en/0 res/1 alloc 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file /home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-service-files/org.freedesktop.DBus.TestSuite.PrivServer.service hnd 00000094 opened 2: 385: [bus/activation.c(418):update_desktop_file_entry] Added "org.freedesktop.DBus.TestSuite.PrivServer" to list of services 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file /home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-service-files/org.freedesktop.DBus.TestSuiteEchoService.service hnd 00000094 opened 2: 385: [bus/activation.c(418):update_desktop_file_entry] Added "org.freedesktop.DBus.TestSuiteEchoService" to list of services 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file /home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-service-files/org.freedesktop.DBus.TestSuiteShellEchoServiceSuccess.service hnd 00000094 opened 2: 385: [bus/activation.c(418):update_desktop_file_entry] Added "org.freedesktop.DBus.TestSuiteShellEchoServiceSuccess" to list of services 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file /home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-service-files/org.freedesktop.DBus.TestSuiteForkingEchoService.service hnd 00000094 opened 2: 385: [bus/activation.c(418):update_desktop_file_entry] Added "org.freedesktop.DBus.TestSuiteForkingEchoService" to list of services 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file /home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-service-files/org.freedesktop.DBus.TestSuiteShellEchoServiceFail.service hnd 00000094 opened 2: 385: [bus/activation.c(418):update_desktop_file_entry] Added "org.freedesktop.DBus.TestSuiteShellEchoServiceFail" to list of services 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file /home/ralf/src/dbus-1-cmake-cross-x86-build/test/data/valid-service-files/org.freedesktop.DBus.TestSuiteSegfaultService.service hnd 00000094 opened 2: 385: [bus/activation.c(418):update_desktop_file_entry] Added "org.freedesktop.DBus.TestSuiteSegfaultService" to list of services 2: 385: [dbus/dbus-dataslot.c(135):_dbus_data_slot_allocator_alloc] Allocated slot 0 on allocator 6DBE404C total 1 slots allocated 1 used 2: 385: [bus/bus.c(913):bus_context_new] Fork not requested 2: 385: [dbus/dbus-sysdeps-util-win.c(188):_dbus_write_pid_to_file_and_pipe] No pid file requested 2: 385: [dbus/dbus-sysdeps-util-win.c(229):_dbus_write_pid_to_file_and_pipe] No pid pipe to write to 2: 385: [dbus/dbus-connection.c(1868):_dbus_connection_open_internal] opening private connection to: debug-pipe:name=test-server 2: 385: [dbus/dbus-sysdeps-win.c(1141):_dbus_socketpair] full-duplex pipe 148:148 <-> 152:152 2: 385: [dbus/dbus-sysdeps-win.c(1029):_dbus_getsid] _dbus_getsid() got 'S-1-5-21-0-0-0-1000' and returns 1 2: 385: [dbus/dbus-auth.c(2165):goto_state] client: going from state NeedSendAuth to state WaitingForData 2: 385: [dbus/dbus-transport.c(204):_dbus_transport_init_base] Initialized transport on address debug-pipe:name=test-server 2: 385: [dbus/dbus-connection.c(1360):_dbus_connection_new_for_transport] LOCK 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 152 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 1 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 0 on connection 002463C0 watch 00243358 fd = 152 outgoing messages exist 0 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(5541):dbus_connection_set_route_peer_messages] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(4963):dbus_connection_set_watch_functions] LOCK 2: 385: [dbus/dbus-watch.c(318):_dbus_watch_list_set_functions] Adding a write watch on fd 152 using newly-set add watch function 2: 385: [dbus/dbus-socket-set-poll.c(136):socket_set_poll_add] inflating set 00243588 from 1 en/1 res/1 alloc to 9 2: 385: [dbus/dbus-socket-set-poll.c(146):socket_set_poll_add] before adding fd 152 to 00243588, 1 en/1 res/9 alloc 2: 385: [dbus/dbus-watch.c(318):_dbus_watch_list_set_functions] Adding a read watch on fd 152 using newly-set add watch function 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(5026):dbus_connection_set_timeout_functions] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(5346):dbus_connection_set_unix_user_function] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(5109):dbus_connection_set_dispatch_status_function] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(5584):dbus_connection_add_filter] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(4384):dbus_connection_get_dispatch_status] start 2: 385: [dbus/dbus-connection.c(4386):dbus_connection_get_dispatch_status] LOCK 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/connection.c(931):bus_connections_expire_incomplete] Connection 002463C0 authentication expires in 29998 milliseconds 2: 385: [bus/expirelist.c(105):bus_expire_timeout_set_interval] Enabled an expire timeout with interval 29998 2: 385: [dbus/dbus-connection.c(6214):dbus_connection_set_max_received_size] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(6119):dbus_connection_set_max_message_size] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(6256):dbus_connection_set_max_received_unix_fds] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(6158):dbus_connection_set_max_message_unix_fds] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(5513):dbus_connection_set_allow_anonymous] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(2150):_dbus_connection_close_if_only_one_ref] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1360):_dbus_connection_new_for_transport] LOCK 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 148 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 0 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 1 on connection 002469B8 watch 002444B8 fd = 148 outgoing messages exist 0 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(5584):dbus_connection_add_filter] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-socket-set-poll.c(98):_dbus_socket_set_poll_new] new socket set at 00246B90 2: 385: [dbus/dbus-connection.c(4963):dbus_connection_set_watch_functions] LOCK 2: 385: [dbus/dbus-watch.c(318):_dbus_watch_list_set_functions] Adding a write watch on fd 148 using newly-set add watch function 2: 385: [dbus/dbus-socket-set-poll.c(146):socket_set_poll_add] before adding fd 148 to 00246B90, 0 en/0 res/1 alloc 2: 385: [dbus/dbus-watch.c(318):_dbus_watch_list_set_functions] Adding a read watch on fd 148 using newly-set add watch function 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(5026):dbus_connection_set_timeout_functions] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/dispatch.c(572):spin_connection_until_authenticated] Spinning to auth connection 002469B8 2: 385: [dbus/dbus-connection.c(3001):dbus_connection_get_is_authenticated] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(2979):dbus_connection_get_is_connected] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/test.c(233):bus_test_run_bus_loop] ---> Dispatching on "server side" 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:136 E:136 2: R:152 E:152 2: 2: [dbus/dbus-sysdeps-win.c(1388):_dbus_poll] select: = 0 2: 385: [bus/test.c(251):bus_test_run_bus_loop] ---> Done dispatching on "server side" 2: 385: [bus/test.c(208):bus_test_run_clients_loop] ---> Dispatching on "client side" 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: W:148 E:148 2: 2: [dbus/dbus-sysdeps-win.c(1410):_dbus_poll] select: = 1: 2: W:148 2: [dbus/dbus-connection.c(1496):_dbus_connection_handle_watch] start 2: 385: [dbus/dbus-connection.c(1498):_dbus_connection_handle_watch] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1074):_dbus_connection_acquire_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1078):_dbus_connection_acquire_io_path] start connection->io_path_acquired = 0 timeout = 1 2: 385: [dbus/dbus-connection.c(1121):_dbus_connection_acquire_io_path] end connection->io_path_acquired = 1 we_acquired = 1 2: 385: [dbus/dbus-connection.c(1123):_dbus_connection_acquire_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1126):_dbus_connection_acquire_io_path] LOCK 2: 385: [dbus/dbus-transport-socket.c(988):socket_handle_watch] handling write watch, have_outgoing_messages = 0 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 0, do_writing = 1 2: 385: [dbus/dbus-sysdeps-win.c(460):_dbus_write_socket] send: len=1 fd=148 2: 385: [dbus/dbus-sysdeps-win.c(470):_dbus_write_socket] send: = 1 2: 385: [dbus/dbus-sysdeps-win.c(1925):_dbus_send_credentials_socket] wrote 1 zero byte, credential sending isn't implemented yet 2: 385: [dbus/dbus-transport-socket.c(464):do_authentication] client auth state: bytes to send 2: 385: [dbus/dbus-sysdeps-win.c(460):_dbus_write_socket] send: len=54 fd=148 2: 385: [dbus/dbus-sysdeps-win.c(470):_dbus_write_socket] send: = 54 2: 385: [dbus/dbus-auth.c(2537):_dbus_auth_bytes_sent] client: Sent 54 bytes of: AUTH EXTERNAL 532d312d352d32312d302d302d302d31303030 2: 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 0, do_writing = 1 2: 385: [dbus/dbus-transport-socket.c(450):do_authentication] client auth state: waiting for input 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 148 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 1 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 002444E8 on fd 148 to 1 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 0 on connection 002469B8 watch 002444B8 fd = 148 outgoing messages exist 0 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 002444B8 on fd 148 to 0 2: 385: [dbus/dbus-transport-socket.c(507):do_writing] Not authenticated, not writing anything 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 0 on connection 002469B8 watch 002444B8 fd = 148 outgoing messages exist 0 2: 385: [dbus/dbus-connection.c(1147):_dbus_connection_release_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1153):_dbus_connection_release_io_path] start connection->io_path_acquired = 1 2: 385: [dbus/dbus-connection.c(1158):_dbus_connection_release_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1515):_dbus_connection_handle_watch] middle 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1522):_dbus_connection_handle_watch] end 2: 385: [dbus/dbus-watch.c(754):dbus_watch_handle] After sanitization, watch flags on fd 148 were 0 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:148 E:148 2: 2: [dbus/dbus-sysdeps-win.c(1388):_dbus_poll] select: = 0 2: 385: [bus/test.c(226):bus_test_run_clients_loop] ---> Done dispatching on "client side" 2: 385: [dbus/dbus-connection.c(3001):dbus_connection_get_is_authenticated] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(2979):dbus_connection_get_is_connected] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/test.c(233):bus_test_run_bus_loop] ---> Dispatching on "server side" 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:136 E:136 2: R:152 E:152 2: 2: [dbus/dbus-sysdeps-win.c(1410):_dbus_poll] select: = 1: 2: R:152 2: [dbus/dbus-connection.c(1496):_dbus_connection_handle_watch] start 2: 385: [dbus/dbus-connection.c(1498):_dbus_connection_handle_watch] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1074):_dbus_connection_acquire_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1078):_dbus_connection_acquire_io_path] start connection->io_path_acquired = 0 timeout = 1 2: 385: [dbus/dbus-connection.c(1121):_dbus_connection_acquire_io_path] end connection->io_path_acquired = 1 we_acquired = 1 2: 385: [dbus/dbus-connection.c(1123):_dbus_connection_acquire_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1126):_dbus_connection_acquire_io_path] LOCK 2: 385: [dbus/dbus-transport-socket.c(959):socket_handle_watch] handling read watch 00246020 flags = 1 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 1, do_writing = 0 2: 385: [dbus/dbus-sysdeps-win.c(400):_dbus_read_socket] recv: count=1 fd=152 2: 385: [dbus/dbus-sysdeps-win.c(410):_dbus_read_socket] recv: = 1 2: 385: [dbus/dbus-sysdeps-win.c(1967):_dbus_read_credentials_socket] got one zero byte from server 2: 385: [dbus/dbus-sysdeps-win.c(291):_dbus_get_peer_pid_from_tcp_handle] trying to get peers pid[dbus/dbus-sysdeps-win.c(186):get_pid_from_extended_tcp_table] got pid 385 2: 385: [dbus/dbus-sysdeps-win.c(1029):_dbus_getsid] _dbus_getsid() got 'S-1-5-21-0-0-0-1000' and returns 1 2: 385: [dbus/dbus-transport-socket.c(450):do_authentication] server auth state: waiting for input 2: 385: [dbus/dbus-sysdeps-win.c(400):_dbus_read_socket] recv: count=2048 fd=152 2: 385: [dbus/dbus-sysdeps-win.c(410):_dbus_read_socket] recv: = 54 2: 385: [dbus/dbus-transport-socket.c(265):read_data_into_auth] read 54 bytes in auth phase 2: 385: [dbus/dbus-auth.c(2218):process_command] server: got command "AUTH EXTERNAL 532d312d352d32312d302d302d302d31303030" 2: 385: [dbus/dbus-auth.c(1746):handle_auth] server: Unsupported mechanism EXTERNAL 2: 385: [dbus/dbus-auth.c(2165):goto_state] server: going from state WaitingForAuth to state WaitingForAuth 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 1, do_writing = 0 2: 385: [dbus/dbus-transport-socket.c(464):do_authentication] server auth state: bytes to send 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 152 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 0 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 00246020 on fd 152 to 0 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 1 on connection 002463C0 watch 00243358 fd = 152 outgoing messages exist 0 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 00243358 on fd 152 to 1 2: 385: [dbus/dbus-transport-socket.c(746):do_reading] fd = 152 2: 385: [dbus/dbus-connection.c(1147):_dbus_connection_release_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1153):_dbus_connection_release_io_path] start connection->io_path_acquired = 1 2: 385: [dbus/dbus-connection.c(1158):_dbus_connection_release_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1515):_dbus_connection_handle_watch] middle 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1522):_dbus_connection_handle_watch] end 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:136 E:136 2: W:152 E:152 2: 2: [dbus/dbus-sysdeps-win.c(1410):_dbus_poll] select: = 1: 2: W:152 2: [dbus/dbus-connection.c(1496):_dbus_connection_handle_watch] start 2: 385: [dbus/dbus-connection.c(1498):_dbus_connection_handle_watch] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1074):_dbus_connection_acquire_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1078):_dbus_connection_acquire_io_path] start connection->io_path_acquired = 0 timeout = 1 2: 385: [dbus/dbus-connection.c(1121):_dbus_connection_acquire_io_path] end connection->io_path_acquired = 1 we_acquired = 1 2: 385: [dbus/dbus-connection.c(1123):_dbus_connection_acquire_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1126):_dbus_connection_acquire_io_path] LOCK 2: 385: [dbus/dbus-transport-socket.c(988):socket_handle_watch] handling write watch, have_outgoing_messages = 0 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 0, do_writing = 1 2: 385: [dbus/dbus-transport-socket.c(464):do_authentication] server auth state: bytes to send 2: 385: [dbus/dbus-sysdeps-win.c(460):_dbus_write_socket] send: len=46 fd=152 2: 385: [dbus/dbus-sysdeps-win.c(470):_dbus_write_socket] send: = 46 2: 385: [dbus/dbus-auth.c(2537):_dbus_auth_bytes_sent] server: Sent 46 bytes of: REJECTED EXTERNAL DBUS_COOKIE_SHA1 ANONYMOUS 2: 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 0, do_writing = 1 2: 385: [dbus/dbus-transport-socket.c(450):do_authentication] server auth state: waiting for input 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 152 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 1 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 00246020 on fd 152 to 1 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 0 on connection 002463C0 watch 00243358 fd = 152 outgoing messages exist 0 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 00243358 on fd 152 to 0 2: 385: [dbus/dbus-transport-socket.c(507):do_writing] Not authenticated, not writing anything 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 0 on connection 002463C0 watch 00243358 fd = 152 outgoing messages exist 0 2: 385: [dbus/dbus-connection.c(1147):_dbus_connection_release_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1153):_dbus_connection_release_io_path] start connection->io_path_acquired = 1 2: 385: [dbus/dbus-connection.c(1158):_dbus_connection_release_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1515):_dbus_connection_handle_watch] middle 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1522):_dbus_connection_handle_watch] end 2: 385: [dbus/dbus-watch.c(754):dbus_watch_handle] After sanitization, watch flags on fd 152 were 0 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:136 E:136 2: R:152 E:152 2: 2: [dbus/dbus-sysdeps-win.c(1388):_dbus_poll] select: = 0 2: 385: [bus/test.c(251):bus_test_run_bus_loop] ---> Done dispatching on "server side" 2: 385: [bus/test.c(208):bus_test_run_clients_loop] ---> Dispatching on "client side" 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:148 E:148 2: 2: [dbus/dbus-sysdeps-win.c(1410):_dbus_poll] select: = 1: 2: R:148 2: [dbus/dbus-connection.c(1496):_dbus_connection_handle_watch] start 2: 385: [dbus/dbus-connection.c(1498):_dbus_connection_handle_watch] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1074):_dbus_connection_acquire_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1078):_dbus_connection_acquire_io_path] start connection->io_path_acquired = 0 timeout = 1 2: 385: [dbus/dbus-connection.c(1121):_dbus_connection_acquire_io_path] end connection->io_path_acquired = 1 we_acquired = 1 2: 385: [dbus/dbus-connection.c(1123):_dbus_connection_acquire_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1126):_dbus_connection_acquire_io_path] LOCK 2: 385: [dbus/dbus-transport-socket.c(959):socket_handle_watch] handling read watch 002444E8 flags = 1 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 1, do_writing = 0 2: 385: [dbus/dbus-transport-socket.c(450):do_authentication] client auth state: waiting for input 2: 385: [dbus/dbus-sysdeps-win.c(400):_dbus_read_socket] recv: count=2048 fd=148 2: 385: [dbus/dbus-sysdeps-win.c(410):_dbus_read_socket] recv: = 46 2: 385: [dbus/dbus-transport-socket.c(265):read_data_into_auth] read 46 bytes in auth phase 2: 385: [dbus/dbus-auth.c(2218):process_command] client: got command "REJECTED EXTERNAL DBUS_COOKIE_SHA1 ANONYMOUS" 2: 385: [dbus/dbus-auth.c(1944):record_mechanisms] client: Already tried mechanism EXTERNAL; not adding to list we will try 2: 385: [dbus/dbus-auth.c(1932):record_mechanisms] client: Adding mechanism DBUS_COOKIE_SHA1 to list we will try 2: 385: [dbus/dbus-auth.c(1932):record_mechanisms] client: Adding mechanism ANONYMOUS to list we will try 2: 385: [dbus/dbus-sysdeps-win.c(1029):_dbus_getsid] _dbus_getsid() got 'S-1-5-21-0-0-0-1000' and returns 1 2: 385: [dbus/dbus-auth.c(430):shutdown_mech] client: Shutting down mechanism EXTERNAL 2: 385: [dbus/dbus-auth.c(2165):goto_state] client: going from state WaitingForData to state WaitingForData 2: 385: [dbus/dbus-auth.c(1992):process_rejected] client: Trying mechanism DBUS_COOKIE_SHA1 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 1, do_writing = 0 2: 385: [dbus/dbus-transport-socket.c(464):do_authentication] client auth state: bytes to send 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 148 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 0 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 002444E8 on fd 148 to 0 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 1 on connection 002469B8 watch 002444B8 fd = 148 outgoing messages exist 0 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 002444B8 on fd 148 to 1 2: 385: [dbus/dbus-transport-socket.c(746):do_reading] fd = 148 2: 385: [dbus/dbus-connection.c(1147):_dbus_connection_release_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1153):_dbus_connection_release_io_path] start connection->io_path_acquired = 1 2: 385: [dbus/dbus-connection.c(1158):_dbus_connection_release_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1515):_dbus_connection_handle_watch] middle 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1522):_dbus_connection_handle_watch] end 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: W:148 E:148 2: 2: [dbus/dbus-sysdeps-win.c(1410):_dbus_poll] select: = 1: 2: W:148 2: [dbus/dbus-connection.c(1496):_dbus_connection_handle_watch] start 2: 385: [dbus/dbus-connection.c(1498):_dbus_connection_handle_watch] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1074):_dbus_connection_acquire_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1078):_dbus_connection_acquire_io_path] start connection->io_path_acquired = 0 timeout = 1 2: 385: [dbus/dbus-connection.c(1121):_dbus_connection_acquire_io_path] end connection->io_path_acquired = 1 we_acquired = 1 2: 385: [dbus/dbus-connection.c(1123):_dbus_connection_acquire_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1126):_dbus_connection_acquire_io_path] LOCK 2: 385: [dbus/dbus-transport-socket.c(988):socket_handle_watch] handling write watch, have_outgoing_messages = 0 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 0, do_writing = 1 2: 385: [dbus/dbus-transport-socket.c(464):do_authentication] client auth state: bytes to send 2: 385: [dbus/dbus-sysdeps-win.c(460):_dbus_write_socket] send: len=62 fd=148 2: 385: [dbus/dbus-sysdeps-win.c(470):_dbus_write_socket] send: = 62 2: 385: [dbus/dbus-auth.c(2537):_dbus_auth_bytes_sent] client: Sent 62 bytes of: AUTH DBUS_COOKIE_SHA1 532d312d352d32312d302d302d302d31303030 2: 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 0, do_writing = 1 2: 385: [dbus/dbus-transport-socket.c(450):do_authentication] client auth state: waiting for input 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 148 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 1 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 002444E8 on fd 148 to 1 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 0 on connection 002469B8 watch 002444B8 fd = 148 outgoing messages exist 0 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 002444B8 on fd 148 to 0 2: 385: [dbus/dbus-transport-socket.c(507):do_writing] Not authenticated, not writing anything 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 0 on connection 002469B8 watch 002444B8 fd = 148 outgoing messages exist 0 2: 385: [dbus/dbus-connection.c(1147):_dbus_connection_release_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1153):_dbus_connection_release_io_path] start connection->io_path_acquired = 1 2: 385: [dbus/dbus-connection.c(1158):_dbus_connection_release_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1515):_dbus_connection_handle_watch] middle 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1522):_dbus_connection_handle_watch] end 2: 385: [dbus/dbus-watch.c(754):dbus_watch_handle] After sanitization, watch flags on fd 148 were 0 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:148 E:148 2: 2: [dbus/dbus-sysdeps-win.c(1388):_dbus_poll] select: = 0 2: 385: [bus/test.c(226):bus_test_run_clients_loop] ---> Done dispatching on "client side" 2: 385: [dbus/dbus-connection.c(3001):dbus_connection_get_is_authenticated] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(2979):dbus_connection_get_is_connected] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/test.c(233):bus_test_run_bus_loop] ---> Dispatching on "server side" 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:136 E:136 2: R:152 E:152 2: 2: [dbus/dbus-sysdeps-win.c(1410):_dbus_poll] select: = 1: 2: R:152 2: [dbus/dbus-connection.c(1496):_dbus_connection_handle_watch] start 2: 385: [dbus/dbus-connection.c(1498):_dbus_connection_handle_watch] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1074):_dbus_connection_acquire_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1078):_dbus_connection_acquire_io_path] start connection->io_path_acquired = 0 timeout = 1 2: 385: [dbus/dbus-connection.c(1121):_dbus_connection_acquire_io_path] end connection->io_path_acquired = 1 we_acquired = 1 2: 385: [dbus/dbus-connection.c(1123):_dbus_connection_acquire_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1126):_dbus_connection_acquire_io_path] LOCK 2: 385: [dbus/dbus-transport-socket.c(959):socket_handle_watch] handling read watch 00246020 flags = 1 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 1, do_writing = 0 2: 385: [dbus/dbus-transport-socket.c(450):do_authentication] server auth state: waiting for input 2: 385: [dbus/dbus-sysdeps-win.c(400):_dbus_read_socket] recv: count=2048 fd=152 2: 385: [dbus/dbus-sysdeps-win.c(410):_dbus_read_socket] recv: = 62 2: 385: [dbus/dbus-transport-socket.c(265):read_data_into_auth] read 62 bytes in auth phase 2: 385: [dbus/dbus-auth.c(2218):process_command] server: got command "AUTH DBUS_COOKIE_SHA1 532d312d352d32312d302d302d302d31303030" 2: 385: [dbus/dbus-auth.c(1735):handle_auth] server: Trying mechanism DBUS_COOKIE_SHA1 2: 385: [dbus/dbus-auth.c(1655):process_data] server: data: 'S-1-5-21-0-0-0-1000' 2: 385: [dbus/dbus-sysdeps-win.c(3399):_dbus_append_keyring_directory_for_credentials] Using fake homedir for testing: z:/home/ralf/src/dbus-1-cmake-cross-x86-build/dbus 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/dbus/.dbus-keyrings/org_freedesktop_general hnd 000000C8 opened 2: 385: [dbus/dbus-keyring.c(555):_dbus_keyring_reload] Successfully loaded 1 existing keys 2: 385: [dbus/dbus-keyring.c(922):find_recent_key] Key 0 is 203 seconds old 2: 385: [dbus/dbus-auth.c(2165):goto_state] server: going from state WaitingForAuth to state WaitingForData 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 1, do_writing = 0 2: 385: [dbus/dbus-transport-socket.c(464):do_authentication] server auth state: bytes to send 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 152 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 0 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 00246020 on fd 152 to 0 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 1 on connection 002463C0 watch 00243358 fd = 152 outgoing messages exist 0 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 00243358 on fd 152 to 1 2: 385: [dbus/dbus-transport-socket.c(746):do_reading] fd = 152 2: 385: [dbus/dbus-connection.c(1147):_dbus_connection_release_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1153):_dbus_connection_release_io_path] start connection->io_path_acquired = 1 2: 385: [dbus/dbus-connection.c(1158):_dbus_connection_release_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1515):_dbus_connection_handle_watch] middle 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1522):_dbus_connection_handle_watch] end 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:136 E:136 2: W:152 E:152 2: 2: [dbus/dbus-sysdeps-win.c(1410):_dbus_poll] select: = 1: 2: W:152 2: [dbus/dbus-connection.c(1496):_dbus_connection_handle_watch] start 2: 385: [dbus/dbus-connection.c(1498):_dbus_connection_handle_watch] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1074):_dbus_connection_acquire_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1078):_dbus_connection_acquire_io_path] start connection->io_path_acquired = 0 timeout = 1 2: 385: [dbus/dbus-connection.c(1121):_dbus_connection_acquire_io_path] end connection->io_path_acquired = 1 we_acquired = 1 2: 385: [dbus/dbus-connection.c(1123):_dbus_connection_acquire_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1126):_dbus_connection_acquire_io_path] LOCK 2: 385: [dbus/dbus-transport-socket.c(988):socket_handle_watch] handling write watch, have_outgoing_messages = 0 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 0, do_writing = 1 2: 385: [dbus/dbus-transport-socket.c(464):do_authentication] server auth state: bytes to send 2: 385: [dbus/dbus-sysdeps-win.c(460):_dbus_write_socket] send: len=139 fd=152 2: 385: [dbus/dbus-sysdeps-win.c(470):_dbus_write_socket] send: = 139 2: 385: [dbus/dbus-auth.c(2537):_dbus_auth_bytes_sent] server: Sent 139 bytes of: DATA 6f72675f667265656465736b746f705f67656e6572616c20373437333536333131203165653665623165386338613633333038346632323764616432613432636630 2: 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 0, do_writing = 1 2: 385: [dbus/dbus-transport-socket.c(450):do_authentication] server auth state: waiting for input 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 152 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 1 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 00246020 on fd 152 to 1 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 0 on connection 002463C0 watch 00243358 fd = 152 outgoing messages exist 0 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 00243358 on fd 152 to 0 2: 385: [dbus/dbus-transport-socket.c(507):do_writing] Not authenticated, not writing anything 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 0 on connection 002463C0 watch 00243358 fd = 152 outgoing messages exist 0 2: 385: [dbus/dbus-connection.c(1147):_dbus_connection_release_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1153):_dbus_connection_release_io_path] start connection->io_path_acquired = 1 2: 385: [dbus/dbus-connection.c(1158):_dbus_connection_release_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1515):_dbus_connection_handle_watch] middle 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1522):_dbus_connection_handle_watch] end 2: 385: [dbus/dbus-watch.c(754):dbus_watch_handle] After sanitization, watch flags on fd 152 were 0 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:136 E:136 2: R:152 E:152 2: 2: [dbus/dbus-sysdeps-win.c(1388):_dbus_poll] select: = 0 2: 385: [bus/test.c(251):bus_test_run_bus_loop] ---> Done dispatching on "server side" 2: 385: [bus/test.c(208):bus_test_run_clients_loop] ---> Dispatching on "client side" 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:148 E:148 2: 2: [dbus/dbus-sysdeps-win.c(1410):_dbus_poll] select: = 1: 2: R:148 2: [dbus/dbus-connection.c(1496):_dbus_connection_handle_watch] start 2: 385: [dbus/dbus-connection.c(1498):_dbus_connection_handle_watch] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1074):_dbus_connection_acquire_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1078):_dbus_connection_acquire_io_path] start connection->io_path_acquired = 0 timeout = 1 2: 385: [dbus/dbus-connection.c(1121):_dbus_connection_acquire_io_path] end connection->io_path_acquired = 1 we_acquired = 1 2: 385: [dbus/dbus-connection.c(1123):_dbus_connection_acquire_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1126):_dbus_connection_acquire_io_path] LOCK 2: 385: [dbus/dbus-transport-socket.c(959):socket_handle_watch] handling read watch 002444E8 flags = 1 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 1, do_writing = 0 2: 385: [dbus/dbus-transport-socket.c(450):do_authentication] client auth state: waiting for input 2: 385: [dbus/dbus-sysdeps-win.c(400):_dbus_read_socket] recv: count=2048 fd=148 2: 385: [dbus/dbus-sysdeps-win.c(410):_dbus_read_socket] recv: = 139 2: 385: [dbus/dbus-transport-socket.c(265):read_data_into_auth] read 139 bytes in auth phase 2: 385: [dbus/dbus-auth.c(2218):process_command] client: got command "DATA 6f72675f667265656465736b746f705f67656e6572616c20373437333536333131203165653665623165386338613633333038346632323764616432613432636630" 2: 385: [dbus/dbus-auth.c(1655):process_data] client: data: 'org_freedesktop_general 747356311 1ee6eb1e8c8a633084f227dad2a42cf0' 2: 385: [dbus/dbus-sysdeps-win.c(1029):_dbus_getsid] _dbus_getsid() got 'S-1-5-21-0-0-0-1000' and returns 1 2: 385: [dbus/dbus-sysdeps-win.c(3399):_dbus_append_keyring_directory_for_credentials] Using fake homedir for testing: z:/home/ralf/src/dbus-1-cmake-cross-x86-build/dbus 2: 385: [dbus/dbus-file-win.c(134):_dbus_file_get_contents] file z:/home/ralf/src/dbus-1-cmake-cross-x86-build/dbus/.dbus-keyrings/org_freedesktop_general hnd 000000C8 opened 2: 385: [dbus/dbus-keyring.c(555):_dbus_keyring_reload] Successfully loaded 1 existing keys 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 1, do_writing = 0 2: 385: [dbus/dbus-transport-socket.c(464):do_authentication] client auth state: bytes to send 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 148 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 0 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 002444E8 on fd 148 to 0 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 1 on connection 002469B8 watch 002444B8 fd = 148 outgoing messages exist 0 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 002444B8 on fd 148 to 1 2: 385: [dbus/dbus-transport-socket.c(746):do_reading] fd = 148 2: 385: [dbus/dbus-connection.c(1147):_dbus_connection_release_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1153):_dbus_connection_release_io_path] start connection->io_path_acquired = 1 2: 385: [dbus/dbus-connection.c(1158):_dbus_connection_release_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1515):_dbus_connection_handle_watch] middle 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1522):_dbus_connection_handle_watch] end 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: W:148 E:148 2: 2: [dbus/dbus-sysdeps-win.c(1410):_dbus_poll] select: = 1: 2: W:148 2: [dbus/dbus-connection.c(1496):_dbus_connection_handle_watch] start 2: 385: [dbus/dbus-connection.c(1498):_dbus_connection_handle_watch] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1074):_dbus_connection_acquire_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1078):_dbus_connection_acquire_io_path] start connection->io_path_acquired = 0 timeout = 1 2: 385: [dbus/dbus-connection.c(1121):_dbus_connection_acquire_io_path] end connection->io_path_acquired = 1 we_acquired = 1 2: 385: [dbus/dbus-connection.c(1123):_dbus_connection_acquire_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1126):_dbus_connection_acquire_io_path] LOCK 2: 385: [dbus/dbus-transport-socket.c(988):socket_handle_watch] handling write watch, have_outgoing_messages = 0 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 0, do_writing = 1 2: 385: [dbus/dbus-transport-socket.c(464):do_authentication] client auth state: bytes to send 2: 385: [dbus/dbus-sysdeps-win.c(460):_dbus_write_socket] send: len=153 fd=148 2: 385: [dbus/dbus-sysdeps-win.c(470):_dbus_write_socket] send: = 153 2: 385: [dbus/dbus-auth.c(2537):_dbus_auth_bytes_sent] client: Sent 153 bytes of: DATA 66336365373038613164303364303037383062396161333530343234313130342035393031316237396434346139356634343564393138623564333631316534323530393838613462 2: 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 0, do_writing = 1 2: 385: [dbus/dbus-transport-socket.c(450):do_authentication] client auth state: waiting for input 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 148 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 1 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 002444E8 on fd 148 to 1 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 0 on connection 002469B8 watch 002444B8 fd = 148 outgoing messages exist 0 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 002444B8 on fd 148 to 0 2: 385: [dbus/dbus-transport-socket.c(507):do_writing] Not authenticated, not writing anything 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 0 on connection 002469B8 watch 002444B8 fd = 148 outgoing messages exist 0 2: 385: [dbus/dbus-connection.c(1147):_dbus_connection_release_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1153):_dbus_connection_release_io_path] start connection->io_path_acquired = 1 2: 385: [dbus/dbus-connection.c(1158):_dbus_connection_release_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1515):_dbus_connection_handle_watch] middle 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1522):_dbus_connection_handle_watch] end 2: 385: [dbus/dbus-watch.c(754):dbus_watch_handle] After sanitization, watch flags on fd 148 were 0 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:148 E:148 2: 2: [dbus/dbus-sysdeps-win.c(1388):_dbus_poll] select: = 0 2: 385: [bus/test.c(226):bus_test_run_clients_loop] ---> Done dispatching on "client side" 2: 385: [dbus/dbus-connection.c(3001):dbus_connection_get_is_authenticated] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(2979):dbus_connection_get_is_connected] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/test.c(233):bus_test_run_bus_loop] ---> Dispatching on "server side" 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:136 E:136 2: R:152 E:152 2: 2: [dbus/dbus-sysdeps-win.c(1410):_dbus_poll] select: = 1: 2: R:152 2: [dbus/dbus-connection.c(1496):_dbus_connection_handle_watch] start 2: 385: [dbus/dbus-connection.c(1498):_dbus_connection_handle_watch] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1074):_dbus_connection_acquire_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1078):_dbus_connection_acquire_io_path] start connection->io_path_acquired = 0 timeout = 1 2: 385: [dbus/dbus-connection.c(1121):_dbus_connection_acquire_io_path] end connection->io_path_acquired = 1 we_acquired = 1 2: 385: [dbus/dbus-connection.c(1123):_dbus_connection_acquire_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1126):_dbus_connection_acquire_io_path] LOCK 2: 385: [dbus/dbus-transport-socket.c(959):socket_handle_watch] handling read watch 00246020 flags = 1 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 1, do_writing = 0 2: 385: [dbus/dbus-transport-socket.c(450):do_authentication] server auth state: waiting for input 2: 385: [dbus/dbus-sysdeps-win.c(400):_dbus_read_socket] recv: count=2048 fd=152 2: 385: [dbus/dbus-sysdeps-win.c(410):_dbus_read_socket] recv: = 153 2: 385: [dbus/dbus-transport-socket.c(265):read_data_into_auth] read 153 bytes in auth phase 2: 385: [dbus/dbus-auth.c(2218):process_command] server: got command "DATA 66336365373038613164303364303037383062396161333530343234313130342035393031316237396434346139356634343564393138623564333631316534323530393838613462" 2: 385: [dbus/dbus-auth.c(1655):process_data] server: data: 'f3ce708a1d03d00780b9aa3504241104 59011b79d44a95f445d918b5d3611e4250988a4b' 2: 385: [dbus/dbus-auth.c(2165):goto_state] server: going from state WaitingForData to state WaitingForBegin 2: 385: [dbus/dbus-auth.c(773):sha1_handle_second_client_response] server: authenticated client using DBUS_COOKIE_SHA1 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 1, do_writing = 0 2: 385: [dbus/dbus-transport-socket.c(464):do_authentication] server auth state: bytes to send 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 152 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 0 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 00246020 on fd 152 to 0 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 1 on connection 002463C0 watch 00243358 fd = 152 outgoing messages exist 0 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 00243358 on fd 152 to 1 2: 385: [dbus/dbus-transport-socket.c(746):do_reading] fd = 152 2: 385: [dbus/dbus-connection.c(1147):_dbus_connection_release_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1153):_dbus_connection_release_io_path] start connection->io_path_acquired = 1 2: 385: [dbus/dbus-connection.c(1158):_dbus_connection_release_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1515):_dbus_connection_handle_watch] middle 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1522):_dbus_connection_handle_watch] end 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:136 E:136 2: W:152 E:152 2: 2: [dbus/dbus-sysdeps-win.c(1410):_dbus_poll] select: = 1: 2: W:152 2: [dbus/dbus-connection.c(1496):_dbus_connection_handle_watch] start 2: 385: [dbus/dbus-connection.c(1498):_dbus_connection_handle_watch] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1074):_dbus_connection_acquire_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1078):_dbus_connection_acquire_io_path] start connection->io_path_acquired = 0 timeout = 1 2: 385: [dbus/dbus-connection.c(1121):_dbus_connection_acquire_io_path] end connection->io_path_acquired = 1 we_acquired = 1 2: 385: [dbus/dbus-connection.c(1123):_dbus_connection_acquire_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1126):_dbus_connection_acquire_io_path] LOCK 2: 385: [dbus/dbus-transport-socket.c(988):socket_handle_watch] handling write watch, have_outgoing_messages = 0 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 0, do_writing = 1 2: 385: [dbus/dbus-transport-socket.c(464):do_authentication] server auth state: bytes to send 2: 385: [dbus/dbus-sysdeps-win.c(460):_dbus_write_socket] send: len=37 fd=152 2: 385: [dbus/dbus-sysdeps-win.c(470):_dbus_write_socket] send: = 37 2: 385: [dbus/dbus-auth.c(2537):_dbus_auth_bytes_sent] server: Sent 37 bytes of: OK dd888b88621788603d4aea185635197a 2: 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 0, do_writing = 1 2: 385: [dbus/dbus-transport-socket.c(450):do_authentication] server auth state: waiting for input 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 152 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 1 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 00246020 on fd 152 to 1 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 0 on connection 002463C0 watch 00243358 fd = 152 outgoing messages exist 0 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 00243358 on fd 152 to 0 2: 385: [dbus/dbus-transport-socket.c(507):do_writing] Not authenticated, not writing anything 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 0 on connection 002463C0 watch 00243358 fd = 152 outgoing messages exist 0 2: 385: [dbus/dbus-connection.c(1147):_dbus_connection_release_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1153):_dbus_connection_release_io_path] start connection->io_path_acquired = 1 2: 385: [dbus/dbus-connection.c(1158):_dbus_connection_release_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1515):_dbus_connection_handle_watch] middle 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1522):_dbus_connection_handle_watch] end 2: 385: [dbus/dbus-watch.c(754):dbus_watch_handle] After sanitization, watch flags on fd 152 were 0 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:136 E:136 2: R:152 E:152 2: 2: [dbus/dbus-sysdeps-win.c(1388):_dbus_poll] select: = 0 2: 385: [bus/test.c(251):bus_test_run_bus_loop] ---> Done dispatching on "server side" 2: 385: [bus/test.c(208):bus_test_run_clients_loop] ---> Dispatching on "client side" 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:148 E:148 2: 2: [dbus/dbus-sysdeps-win.c(1410):_dbus_poll] select: = 1: 2: R:148 2: [dbus/dbus-connection.c(1496):_dbus_connection_handle_watch] start 2: 385: [dbus/dbus-connection.c(1498):_dbus_connection_handle_watch] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1074):_dbus_connection_acquire_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1078):_dbus_connection_acquire_io_path] start connection->io_path_acquired = 0 timeout = 1 2: 385: [dbus/dbus-connection.c(1121):_dbus_connection_acquire_io_path] end connection->io_path_acquired = 1 we_acquired = 1 2: 385: [dbus/dbus-connection.c(1123):_dbus_connection_acquire_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1126):_dbus_connection_acquire_io_path] LOCK 2: 385: [dbus/dbus-transport-socket.c(959):socket_handle_watch] handling read watch 002444E8 flags = 1 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 1, do_writing = 0 2: 385: [dbus/dbus-transport-socket.c(450):do_authentication] client auth state: waiting for input 2: 385: [dbus/dbus-sysdeps-win.c(400):_dbus_read_socket] recv: count=2048 fd=148 2: 385: [dbus/dbus-sysdeps-win.c(410):_dbus_read_socket] recv: = 37 2: 385: [dbus/dbus-transport-socket.c(265):read_data_into_auth] read 37 bytes in auth phase 2: 385: [dbus/dbus-auth.c(2218):process_command] client: got command "OK dd888b88621788603d4aea185635197a" 2: 385: [dbus/dbus-auth.c(1603):process_ok] Got GUID 'dd888b88621788603d4aea185635197a' from the server 2: 385: [dbus/dbus-auth.c(1608):process_ok] Not negotiating unix fd passing, since not possible 2: 385: [dbus/dbus-auth.c(2165):goto_state] client: going from state WaitingForData to state Authenticated 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 1, do_writing = 0 2: 385: [dbus/dbus-transport-socket.c(464):do_authentication] client auth state: bytes to send 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 148 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 0 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 002444E8 on fd 148 to 0 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 1 on connection 002469B8 watch 002444B8 fd = 148 outgoing messages exist 0 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 002444B8 on fd 148 to 1 2: 385: [dbus/dbus-transport-socket.c(746):do_reading] fd = 148 2: 385: [dbus/dbus-connection.c(1147):_dbus_connection_release_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1153):_dbus_connection_release_io_path] start connection->io_path_acquired = 1 2: 385: [dbus/dbus-connection.c(1158):_dbus_connection_release_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1515):_dbus_connection_handle_watch] middle 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1522):_dbus_connection_handle_watch] end 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: W:148 E:148 2: 2: [dbus/dbus-sysdeps-win.c(1410):_dbus_poll] select: = 1: 2: W:148 2: [dbus/dbus-connection.c(1496):_dbus_connection_handle_watch] start 2: 385: [dbus/dbus-connection.c(1498):_dbus_connection_handle_watch] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1074):_dbus_connection_acquire_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1078):_dbus_connection_acquire_io_path] start connection->io_path_acquired = 0 timeout = 1 2: 385: [dbus/dbus-connection.c(1121):_dbus_connection_acquire_io_path] end connection->io_path_acquired = 1 we_acquired = 1 2: 385: [dbus/dbus-connection.c(1123):_dbus_connection_acquire_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1126):_dbus_connection_acquire_io_path] LOCK 2: 385: [dbus/dbus-transport-socket.c(988):socket_handle_watch] handling write watch, have_outgoing_messages = 0 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 0, do_writing = 1 2: 385: [dbus/dbus-transport-socket.c(464):do_authentication] client auth state: bytes to send 2: 385: [dbus/dbus-sysdeps-win.c(460):_dbus_write_socket] send: len=7 fd=148 2: 385: [dbus/dbus-sysdeps-win.c(470):_dbus_write_socket] send: = 7 2: 385: [dbus/dbus-auth.c(2537):_dbus_auth_bytes_sent] client: Sent 7 bytes of: BEGIN 2: 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 148 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 1 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 002444E8 on fd 148 to 1 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 0 on connection 002469B8 watch 002444B8 fd = 148 outgoing messages exist 0 2: 385: [dbus/dbus-watch.c(458):_dbus_watch_list_toggle_watch] Toggling watch 002444B8 on fd 148 to 0 2: 385: [dbus/dbus-transport-socket.c(520):do_writing] do_writing(), have_messages = 0, fd = 148 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 0 on connection 002469B8 watch 002444B8 fd = 148 outgoing messages exist 0 2: 385: [dbus/dbus-connection.c(1147):_dbus_connection_release_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1153):_dbus_connection_release_io_path] start connection->io_path_acquired = 1 2: 385: [dbus/dbus-connection.c(1158):_dbus_connection_release_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1515):_dbus_connection_handle_watch] middle 2: 385: [dbus/dbus-transport.c(1075):recover_unused_bytes] 0 unused bytes sent to message loader 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1522):_dbus_connection_handle_watch] end 2: 385: [dbus/dbus-watch.c(754):dbus_watch_handle] After sanitization, watch flags on fd 148 were 0 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:148 E:148 2: 2: [dbus/dbus-sysdeps-win.c(1388):_dbus_poll] select: = 0 2: 385: [bus/test.c(226):bus_test_run_clients_loop] ---> Done dispatching on "client side" 2: 385: [dbus/dbus-connection.c(3001):dbus_connection_get_is_authenticated] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/dispatch.c(579):spin_connection_until_authenticated] ... done spinning to auth connection 002469B8 2: 385: [bus/dispatch.c(888):check_hello_message] check_hello_message for 002469B8 2: 385: [dbus/dbus-connection.c(3309):dbus_connection_send] LOCK 2: 385: [dbus/dbus-connection.c(2034):_dbus_connection_send_preallocated_unlocked_no_update] Message 00244FA0 (method_call /org/freedesktop/DBus org.freedesktop.DBus Hello '') for org.freedesktop.DBus added to outgoing queue 002469B8, 1 pending to send 2: 385: [dbus/dbus-connection.c(2050):_dbus_connection_send_preallocated_unlocked_no_update] Message 00244FA0 serial is 1 2: 385: [dbus/dbus-connection.c(1203):_dbus_connection_do_iteration_unlocked] start 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1074):_dbus_connection_acquire_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1078):_dbus_connection_acquire_io_path] start connection->io_path_acquired = 0 timeout = 0 2: 385: [dbus/dbus-connection.c(1121):_dbus_connection_acquire_io_path] end connection->io_path_acquired = 1 we_acquired = 1 2: 385: [dbus/dbus-connection.c(1123):_dbus_connection_acquire_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1126):_dbus_connection_acquire_io_path] LOCK 2: 385: [dbus/dbus-transport.c(991):_dbus_transport_do_iteration] Transport iteration flags 0x1 timeout -1 connected = 1 2: 385: [dbus/dbus-transport-socket.c(1087):socket_do_iteration] iteration flags = write timeout = -1 read_watch = 002444E8 write_watch = 002444B8 fd = 148 2: 385: [dbus/dbus-transport-socket.c(520):do_writing] do_writing(), have_messages = 1, fd = 148 2: 385: [dbus/dbus-sysdeps-win.c(621):_dbus_write_socket_two] WSASend: len1+2=128+0 fd=148 2: 385: [dbus/dbus-sysdeps-win.c(637):_dbus_write_socket_two] WSASend: = 128 2: 385: [dbus/dbus-transport-socket.c(707):do_writing] wrote 128 bytes of 128 2: 385: [dbus/dbus-connection.c(660):_dbus_connection_message_sent_unlocked] Message 00244FA0 (method_call /org/freedesktop/DBus org.freedesktop.DBus Hello '') removed from outgoing queue 002469B8, 0 left to send 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 0 on connection 002469B8 watch 002444B8 fd = 148 outgoing messages exist 0 2: 385: [dbus/dbus-transport-socket.c(1231):socket_do_iteration] ... leaving do_iteration() 2: 385: [dbus/dbus-transport.c(1005):_dbus_transport_do_iteration] end 2: 385: [dbus/dbus-connection.c(1147):_dbus_connection_release_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1153):_dbus_connection_release_io_path] start connection->io_path_acquired = 1 2: 385: [dbus/dbus-connection.c(1158):_dbus_connection_release_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1236):_dbus_connection_do_iteration_unlocked] end 2: 385: [dbus/dbus-connection.c(2081):_dbus_connection_send_preallocated_and_unlock] middle 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(2979):dbus_connection_get_is_connected] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(594):dbus_connection_has_messages_to_send] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/test.c(208):bus_test_run_clients_loop] ---> Dispatching on "client side" 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:148 E:148 2: 2: [dbus/dbus-sysdeps-win.c(1388):_dbus_poll] select: = 0 2: 385: [bus/test.c(226):bus_test_run_clients_loop] ---> Done dispatching on "client side" 2: 385: [dbus/dbus-connection.c(2979):dbus_connection_get_is_connected] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/dispatch.c(557):block_connection_until_message_from_bus] expecting: reply to Hello 2: 385: [dbus/dbus-connection.c(4384):dbus_connection_get_dispatch_status] start 2: 385: [dbus/dbus-connection.c(4386):dbus_connection_get_dispatch_status] LOCK 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(2979):dbus_connection_get_is_connected] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/test.c(233):bus_test_run_bus_loop] ---> Dispatching on "server side" 2: 385: [bus/test.c(243):bus_test_run_bus_loop] ---> blocking on "server side" 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=29958 2: R:136 E:136 2: R:152 E:152 2: 2: [dbus/dbus-sysdeps-win.c(1410):_dbus_poll] select: = 1: 2: R:152 2: [dbus/dbus-connection.c(1496):_dbus_connection_handle_watch] start 2: 385: [dbus/dbus-connection.c(1498):_dbus_connection_handle_watch] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1074):_dbus_connection_acquire_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1078):_dbus_connection_acquire_io_path] start connection->io_path_acquired = 0 timeout = 1 2: 385: [dbus/dbus-connection.c(1121):_dbus_connection_acquire_io_path] end connection->io_path_acquired = 1 we_acquired = 1 2: 385: [dbus/dbus-connection.c(1123):_dbus_connection_acquire_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1126):_dbus_connection_acquire_io_path] LOCK 2: 385: [dbus/dbus-transport-socket.c(959):socket_handle_watch] handling read watch 00246020 flags = 1 2: 385: [dbus/dbus-transport-socket.c(349):exchange_credentials] exchange_credentials: do_reading = 1, do_writing = 0 2: 385: [dbus/dbus-transport-socket.c(450):do_authentication] server auth state: waiting for input 2: 385: [dbus/dbus-sysdeps-win.c(400):_dbus_read_socket] recv: count=2048 fd=152 2: 385: [dbus/dbus-sysdeps-win.c(410):_dbus_read_socket] recv: = 7 2: 385: [dbus/dbus-transport-socket.c(265):read_data_into_auth] read 7 bytes in auth phase 2: 385: [dbus/dbus-auth.c(2218):process_command] server: got command "BEGIN" 2: 385: [dbus/dbus-auth.c(2165):goto_state] server: going from state WaitingForBegin to state Authenticated 2: 385: [dbus/dbus-sysdeps-win.c(1029):_dbus_getsid] _dbus_getsid() got 'S-1-5-21-0-0-0-1000' and returns 1 2: 385: [dbus/dbus-transport.c(657):auth_via_default_rules] Client authorized as SID 'S-1-5-21-0-0-0-1000'matching our SID 'S-1-5-21-0-0-0-1000' 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 152 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 1 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 0 on connection 002463C0 watch 00243358 fd = 152 outgoing messages exist 0 2: 385: [dbus/dbus-transport-socket.c(980):socket_handle_watch] Not reading anything since we just completed the authentication 2: 385: [dbus/dbus-connection.c(1147):_dbus_connection_release_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1153):_dbus_connection_release_io_path] start connection->io_path_acquired = 1 2: 385: [dbus/dbus-connection.c(1158):_dbus_connection_release_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1515):_dbus_connection_handle_watch] middle 2: 385: [dbus/dbus-transport.c(1075):recover_unused_bytes] 0 unused bytes sent to message loader 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1522):_dbus_connection_handle_watch] end 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:136 E:136 2: R:152 E:152 2: 2: [dbus/dbus-sysdeps-win.c(1388):_dbus_poll] select: = 0 2: 385: [bus/test.c(251):bus_test_run_bus_loop] ---> Done dispatching on "server side" 2: 385: [bus/test.c(208):bus_test_run_clients_loop] ---> Dispatching on "client side" 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:148 E:148 2: 2: [dbus/dbus-sysdeps-win.c(1388):_dbus_poll] select: = 0 2: 385: [bus/test.c(226):bus_test_run_clients_loop] ---> Done dispatching on "client side" 2: 385: [dbus/dbus-connection.c(4384):dbus_connection_get_dispatch_status] start 2: 385: [dbus/dbus-connection.c(4386):dbus_connection_get_dispatch_status] LOCK 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(2979):dbus_connection_get_is_connected] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/test.c(233):bus_test_run_bus_loop] ---> Dispatching on "server side" 2: 385: [bus/test.c(243):bus_test_run_bus_loop] ---> blocking on "server side" 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=29956 2: R:136 E:136 2: R:152 E:152 2: 2: [dbus/dbus-sysdeps-win.c(1410):_dbus_poll] select: = 1: 2: R:152 2: [dbus/dbus-connection.c(1496):_dbus_connection_handle_watch] start 2: 385: [dbus/dbus-connection.c(1498):_dbus_connection_handle_watch] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1074):_dbus_connection_acquire_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1078):_dbus_connection_acquire_io_path] start connection->io_path_acquired = 0 timeout = 1 2: 385: [dbus/dbus-connection.c(1121):_dbus_connection_acquire_io_path] end connection->io_path_acquired = 1 we_acquired = 1 2: 385: [dbus/dbus-connection.c(1123):_dbus_connection_acquire_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1126):_dbus_connection_acquire_io_path] LOCK 2: 385: [dbus/dbus-transport-socket.c(959):socket_handle_watch] handling read watch 00246020 flags = 1 2: 385: [dbus/dbus-transport-socket.c(746):do_reading] fd = 152 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 152 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 1 2: 385: [dbus/dbus-sysdeps-win.c(400):_dbus_read_socket] recv: count=2048 fd=152 2: 385: [dbus/dbus-sysdeps-win.c(410):_dbus_read_socket] recv: = 128 2: 385: [dbus/dbus-transport-socket.c(887):do_reading] read 128 bytes 2: 385: [dbus/dbus-marshal-header.c(747):_dbus_header_have_message_untrusted] have 128 bytes, need body 0 + header 128 = 128 2: 385: [dbus/dbus-marshal-validate.c(723):_dbus_validate_body_with_reason] validating body from pos 0 len 128 sig 'yyyyuua(yv)' 2: 385: [dbus/dbus-marshal-header.c(821):load_and_validate_field] initially caching field 1 2: 385: [dbus/dbus-marshal-header.c(821):load_and_validate_field] initially caching field 6 2: 385: [dbus/dbus-marshal-header.c(821):load_and_validate_field] initially caching field 2 2: 385: [dbus/dbus-marshal-header.c(821):load_and_validate_field] initially caching field 3 2: 385: [dbus/dbus-marshal-validate.c(723):_dbus_validate_body_with_reason] validating body from pos 128 len 0 sig '' 2: 385: [dbus/dbus-message.c(4297):load_message] Loaded message 00244FA0 2: 385: [dbus/dbus-transport.c(1159):_dbus_transport_queue_messages] queueing received message 00244FA0 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 152 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 1 2: 385: [dbus/dbus-connection.c(530):_dbus_connection_queue_received_message_link] Message 00244FA0 (method_call /org/freedesktop/DBus org.freedesktop.DBus Hello '' reply to 0) added to incoming queue 002463C0, 1 incoming 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 152 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 1 2: 385: [dbus/dbus-sysdeps-win.c(400):_dbus_read_socket] recv: count=2048 fd=152 2: 385: [dbus/dbus-sysdeps-win.c(406):_dbus_read_socket] recv: failed: Resource temporarily unavailable (10035) 2: 385: [dbus/dbus-connection.c(1147):_dbus_connection_release_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1153):_dbus_connection_release_io_path] start connection->io_path_acquired = 1 2: 385: [dbus/dbus-connection.c(1158):_dbus_connection_release_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1515):_dbus_connection_handle_watch] middle 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(4345):_dbus_connection_update_dispatch_status_and_unlock] Notifying of change to dispatch status of 002463C0 now 0 (data remains) 2: 385: [dbus/dbus-connection.c(1522):_dbus_connection_handle_watch] end 2: 385: [dbus/dbus-connection.c(4587):dbus_connection_dispatch] 2: 385: [dbus/dbus-connection.c(4589):dbus_connection_dispatch] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(4136):_dbus_connection_acquire_dispatch] locking dispatch_mutex 2: 385: [dbus/dbus-connection.c(4150):_dbus_connection_acquire_dispatch] unlocking dispatch_mutex 2: 385: [dbus/dbus-connection.c(4153):_dbus_connection_acquire_dispatch] LOCK 2: 385: [dbus/dbus-connection.c(4000):_dbus_connection_pop_message_link_unlocked] Message 00244FA0 (method_call /org/freedesktop/DBus org.freedesktop.DBus Hello sig:'' serial:1) removed from incoming queue 002463C0, 0 incoming 2: 385: [dbus/dbus-connection.c(4635):dbus_connection_dispatch] dispatching message 00244FA0 (method_call org.freedesktop.DBus Hello '') 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(4702):dbus_connection_dispatch] running filter on message 00244FA0 2: 385: [dbus/dbus-connection.c(3171):dbus_connection_preallocate_send] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/dispatch.c(302):bus_dispatch] DISPATCH: org.freedesktop.DBus Hello (no error name) to org.freedesktop.DBus 2: 385: [bus/bus.c(1646):bus_context_check_security_policy] security check allowing Hello message 2: 385: [bus/dispatch.c(389):bus_dispatch] Giving message to org.freedesktop.DBus 2: 385: [bus/driver.c(2433):bus_driver_handle_message] Driver got a method call: Hello 2: 385: [bus/driver.c(2451):bus_driver_handle_message] Found driver handler for Hello 2: 385: [dbus/dbus-connection.c(5229):dbus_connection_get_unix_user] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/connection.c(1517):bus_connection_complete] Name :1.0 assigned to 002463C0 2: 385: [dbus/dbus-connection.c(3001):dbus_connection_get_is_authenticated] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/policy.c(861):bus_client_policy_append_rule] Appending rule 00245B80 with type 0 to policy 00244F40 2: 385: [bus/policy.c(861):bus_client_policy_append_rule] Appending rule 00245BE0 with type 1 to policy 00244F40 2: 385: [bus/policy.c(861):bus_client_policy_append_rule] Appending rule 00245C40 with type 2 to policy 00244F40 2: 385: [dbus/dbus-connection.c(5229):dbus_connection_get_unix_user] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/policy.c(799):bus_client_policy_optimize] Optimizing policy with 3 rules 2: 385: [bus/policy.c(853):bus_client_policy_optimize] After optimization, policy has 3 rules 2: 385: [dbus/dbus-connection.c(5229):dbus_connection_get_unix_user] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(5229):dbus_connection_get_unix_user] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(5265):dbus_connection_get_unix_process_id] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(5422):dbus_connection_get_windows_user] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/expirelist.c(111):bus_expire_timeout_set_interval] Disabled an expire timeout 2: 385: [bus/connection.c(2277):bus_transaction_send_from_driver] Sending (no interface) (no member) (no error name) from driver 2: 385: [bus/policy.c(1074):bus_client_policy_check_can_receive] (policy) checking receive rules, eavesdropping = 0 2: 385: [bus/policy.c(1087):bus_client_policy_check_can_receive] (policy) skipping non-receive rule 2: 385: [bus/policy.c(1243):bus_client_policy_check_can_receive] (policy) used rule, allow now = 1 2: 385: [bus/policy.c(1087):bus_client_policy_check_can_receive] (policy) skipping non-receive rule 2: 385: [dbus/dbus-connection.c(6298):dbus_connection_get_outgoing_size] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(6359):dbus_connection_get_outgoing_unix_fds] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/bus.c(1778):bus_context_check_security_policy] security policy allowing message 2: 385: [dbus/dbus-connection.c(2979):dbus_connection_get_is_connected] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/connection.c(2343):bus_transaction_send] trying to add reply interface=(unset) member=(unset) error=(unset) to transaction 2: 385: [dbus/dbus-connection.c(2979):dbus_connection_get_is_connected] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(3171):dbus_connection_preallocate_send] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/connection.c(2370):bus_transaction_send] about to prepend message 2: 385: [bus/connection.c(2378):bus_transaction_send] prepended message 2: 385: [bus/services.c(273):bus_registry_ensure] copying string 006CF780 ':1.0' to service->name 2: 385: [bus/services.c(282):bus_registry_ensure] copied string 006CF780 ':1.0' to ':1.0' 2: 385: [bus/driver.c(222):bus_driver_send_service_owner_changed] sending name owner changed: :1.0 [ -> :1.0] 2: 385: [bus/signals.c(1333):bus_matchmaker_get_rules] Looking up rules for message_type 0, interface 2: 385: [bus/signals.c(1333):bus_matchmaker_get_rules] Looking up rules for message_type 0, interface org.freedesktop.DBus 2: 385: [bus/signals.c(1333):bus_matchmaker_get_rules] Looking up rules for message_type 4, interface 2: 385: [bus/signals.c(1333):bus_matchmaker_get_rules] Looking up rules for message_type 4, interface org.freedesktop.DBus 2: 385: [bus/connection.c(2277):bus_transaction_send_from_driver] Sending org.freedesktop.DBus NameAcquired (no error name) from driver 2: 385: [bus/policy.c(1074):bus_client_policy_check_can_receive] (policy) checking receive rules, eavesdropping = 0 2: 385: [bus/policy.c(1087):bus_client_policy_check_can_receive] (policy) skipping non-receive rule 2: 385: [bus/policy.c(1243):bus_client_policy_check_can_receive] (policy) used rule, allow now = 1 2: 385: [bus/policy.c(1087):bus_client_policy_check_can_receive] (policy) skipping non-receive rule 2: 385: [dbus/dbus-connection.c(6298):dbus_connection_get_outgoing_size] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(6359):dbus_connection_get_outgoing_unix_fds] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/bus.c(1778):bus_context_check_security_policy] security policy allowing message 2: 385: [dbus/dbus-connection.c(2979):dbus_connection_get_is_connected] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/connection.c(2343):bus_transaction_send] trying to add message interface=org.freedesktop.DBus member=NameAcquired error=(unset) to transaction 2: 385: [dbus/dbus-connection.c(2979):dbus_connection_get_is_connected] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(3171):dbus_connection_preallocate_send] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/connection.c(2370):bus_transaction_send] about to prepend message 2: 385: [bus/connection.c(2378):bus_transaction_send] prepended message 2: 385: [bus/connection.c(2586):bus_transaction_add_cancel_hook] adding cancel hook function = 0042529B data = 0024CB88 2: 385: [bus/driver.c(2471):bus_driver_handle_message] Driver handler succeeded 2: 385: [bus/signals.c(1333):bus_matchmaker_get_rules] Looking up rules for message_type 0, interface 2: 385: [bus/signals.c(1333):bus_matchmaker_get_rules] Looking up rules for message_type 0, interface org.freedesktop.DBus 2: 385: [bus/signals.c(1333):bus_matchmaker_get_rules] Looking up rules for message_type 1, interface 2: 385: [bus/signals.c(1333):bus_matchmaker_get_rules] Looking up rules for message_type 1, interface org.freedesktop.DBus 2: 385: [bus/connection.c(2511):bus_transaction_execute_and_free] TRANSACTION: executing 2: 385: [dbus/dbus-connection.c(3232):dbus_connection_send_preallocated] LOCK 2: 385: [dbus/dbus-connection.c(2034):_dbus_connection_send_preallocated_unlocked_no_update] Message 00245018 (method_return no path no interface no member 's') for :1.0 added to outgoing queue 002463C0, 1 pending to send 2: 385: [dbus/dbus-connection.c(2050):_dbus_connection_send_preallocated_unlocked_no_update] Message 00245018 serial is 1 2: 385: [dbus/dbus-connection.c(1203):_dbus_connection_do_iteration_unlocked] start 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1074):_dbus_connection_acquire_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1078):_dbus_connection_acquire_io_path] start connection->io_path_acquired = 0 timeout = 0 2: 385: [dbus/dbus-connection.c(1121):_dbus_connection_acquire_io_path] end connection->io_path_acquired = 1 we_acquired = 1 2: 385: [dbus/dbus-connection.c(1123):_dbus_connection_acquire_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1126):_dbus_connection_acquire_io_path] LOCK 2: 385: [dbus/dbus-transport.c(991):_dbus_transport_do_iteration] Transport iteration flags 0x1 timeout -1 connected = 1 2: 385: [dbus/dbus-transport-socket.c(1087):socket_do_iteration] iteration flags = write timeout = -1 read_watch = 00246020 write_watch = 00243358 fd = 152 2: 385: [dbus/dbus-transport-socket.c(520):do_writing] do_writing(), have_messages = 1, fd = 152 2: 385: [dbus/dbus-sysdeps-win.c(621):_dbus_write_socket_two] WSASend: len1+2=80+9 fd=152 2: 385: [dbus/dbus-sysdeps-win.c(637):_dbus_write_socket_two] WSASend: = 89 2: 385: [dbus/dbus-transport-socket.c(707):do_writing] wrote 89 bytes of 89 2: 385: [dbus/dbus-connection.c(660):_dbus_connection_message_sent_unlocked] Message 00245018 (method_return no path no interface no member 's') removed from outgoing queue 002463C0, 0 left to send 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 0 on connection 002463C0 watch 00243358 fd = 152 outgoing messages exist 0 2: 385: [dbus/dbus-transport-socket.c(1231):socket_do_iteration] ... leaving do_iteration() 2: 385: [dbus/dbus-transport.c(1005):_dbus_transport_do_iteration] end 2: 385: [dbus/dbus-connection.c(1147):_dbus_connection_release_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1153):_dbus_connection_release_io_path] start connection->io_path_acquired = 1 2: 385: [dbus/dbus-connection.c(1158):_dbus_connection_release_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1236):_dbus_connection_do_iteration_unlocked] end 2: 385: [dbus/dbus-connection.c(2081):_dbus_connection_send_preallocated_and_unlock] middle 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(4345):_dbus_connection_update_dispatch_status_and_unlock] Notifying of change to dispatch status of 002463C0 now 1 (complete) 2: 385: [dbus/dbus-connection.c(3232):dbus_connection_send_preallocated] LOCK 2: 385: [dbus/dbus-connection.c(2034):_dbus_connection_send_preallocated_unlocked_no_update] Message 0024C918 (signal /org/freedesktop/DBus org.freedesktop.DBus NameAcquired 's') for :1.0 added to outgoing queue 002463C0, 1 pending to send 2: 385: [dbus/dbus-connection.c(2050):_dbus_connection_send_preallocated_unlocked_no_update] Message 0024C918 serial is 2 2: 385: [dbus/dbus-connection.c(1203):_dbus_connection_do_iteration_unlocked] start 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1074):_dbus_connection_acquire_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1078):_dbus_connection_acquire_io_path] start connection->io_path_acquired = 0 timeout = 0 2: 385: [dbus/dbus-connection.c(1121):_dbus_connection_acquire_io_path] end connection->io_path_acquired = 1 we_acquired = 1 2: 385: [dbus/dbus-connection.c(1123):_dbus_connection_acquire_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1126):_dbus_connection_acquire_io_path] LOCK 2: 385: [dbus/dbus-transport.c(991):_dbus_transport_do_iteration] Transport iteration flags 0x1 timeout -1 connected = 1 2: 385: [dbus/dbus-transport-socket.c(1087):socket_do_iteration] iteration flags = write timeout = -1 read_watch = 00246020 write_watch = 00243358 fd = 152 2: 385: [dbus/dbus-transport-socket.c(520):do_writing] do_writing(), have_messages = 1, fd = 152 2: 385: [dbus/dbus-sysdeps-win.c(621):_dbus_write_socket_two] WSASend: len1+2=160+9 fd=152 2: 385: [dbus/dbus-sysdeps-win.c(637):_dbus_write_socket_two] WSASend: = 169 2: 385: [dbus/dbus-transport-socket.c(707):do_writing] wrote 169 bytes of 169 2: 385: [dbus/dbus-connection.c(660):_dbus_connection_message_sent_unlocked] Message 0024C918 (signal /org/freedesktop/DBus org.freedesktop.DBus NameAcquired 's') removed from outgoing queue 002463C0, 0 left to send 2: 385: [dbus/dbus-transport-socket.c(165):check_write_watch] check_write_watch(): needed = 0 on connection 002463C0 watch 00243358 fd = 152 outgoing messages exist 0 2: 385: [dbus/dbus-transport-socket.c(1231):socket_do_iteration] ... leaving do_iteration() 2: 385: [dbus/dbus-transport.c(1005):_dbus_transport_do_iteration] end 2: 385: [dbus/dbus-connection.c(1147):_dbus_connection_release_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1153):_dbus_connection_release_io_path] start connection->io_path_acquired = 1 2: 385: [dbus/dbus-connection.c(1158):_dbus_connection_release_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1236):_dbus_connection_do_iteration_unlocked] end 2: 385: [dbus/dbus-connection.c(2081):_dbus_connection_send_preallocated_and_unlock] middle 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(4716):dbus_connection_dispatch] LOCK 2: 385: [dbus/dbus-connection.c(4725):dbus_connection_dispatch] filter handled message in dispatch 2: 385: [dbus/dbus-connection.c(4856):dbus_connection_dispatch] ... done dispatching 2: 385: [dbus/dbus-connection.c(4169):_dbus_connection_release_dispatch] locking dispatch_mutex 2: 385: [dbus/dbus-connection.c(4177):_dbus_connection_release_dispatch] unlocking dispatch_mutex 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(4873):dbus_connection_dispatch] LOCK 2: 385: [dbus/dbus-connection.c(4879):dbus_connection_dispatch] before final status update 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:136 E:136 2: R:152 E:152 2: 2: [dbus/dbus-sysdeps-win.c(1388):_dbus_poll] select: = 0 2: 385: [bus/test.c(251):bus_test_run_bus_loop] ---> Done dispatching on "server side" 2: 385: [bus/test.c(208):bus_test_run_clients_loop] ---> Dispatching on "client side" 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:148 E:148 2: 2: [dbus/dbus-sysdeps-win.c(1410):_dbus_poll] select: = 1: 2: R:148 2: [dbus/dbus-connection.c(1496):_dbus_connection_handle_watch] start 2: 385: [dbus/dbus-connection.c(1498):_dbus_connection_handle_watch] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1074):_dbus_connection_acquire_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1078):_dbus_connection_acquire_io_path] start connection->io_path_acquired = 0 timeout = 1 2: 385: [dbus/dbus-connection.c(1121):_dbus_connection_acquire_io_path] end connection->io_path_acquired = 1 we_acquired = 1 2: 385: [dbus/dbus-connection.c(1123):_dbus_connection_acquire_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1126):_dbus_connection_acquire_io_path] LOCK 2: 385: [dbus/dbus-transport-socket.c(959):socket_handle_watch] handling read watch 002444E8 flags = 1 2: 385: [dbus/dbus-transport-socket.c(746):do_reading] fd = 148 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 148 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 1 2: 385: [dbus/dbus-sysdeps-win.c(400):_dbus_read_socket] recv: count=2048 fd=148 2: 385: [dbus/dbus-sysdeps-win.c(410):_dbus_read_socket] recv: = 89 2: 385: [dbus/dbus-transport-socket.c(887):do_reading] read 89 bytes 2: 385: [dbus/dbus-marshal-header.c(747):_dbus_header_have_message_untrusted] have 89 bytes, need body 9 + header 80 = 89 2: 385: [dbus/dbus-marshal-validate.c(723):_dbus_validate_body_with_reason] validating body from pos 0 len 89 sig 'yyyyuua(yv)' 2: 385: [dbus/dbus-marshal-validate.c(548):validate_body_helper] p = 0024CCB7 end = 0024CCE1 claimed_len 1 2: 385: [dbus/dbus-marshal-header.c(821):load_and_validate_field] initially caching field 6 2: 385: [dbus/dbus-marshal-header.c(821):load_and_validate_field] initially caching field 5 2: 385: [dbus/dbus-marshal-header.c(821):load_and_validate_field] initially caching field 8 2: 385: [dbus/dbus-marshal-header.c(821):load_and_validate_field] initially caching field 7 2: 385: [dbus/dbus-marshal-validate.c(723):_dbus_validate_body_with_reason] validating body from pos 80 len 9 sig 's' 2: 385: [dbus/dbus-message.c(4297):load_message] Loaded message 00245018 2: 385: [dbus/dbus-transport.c(1159):_dbus_transport_queue_messages] queueing received message 00245018 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 148 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 1 2: 385: [dbus/dbus-connection.c(530):_dbus_connection_queue_received_message_link] Message 00245018 (method_return no path no interface no member 's' reply to 1) added to incoming queue 002469B8, 1 incoming 2: 385: [dbus/dbus-transport-socket.c(181):check_read_watch] fd = 148 2: 385: [dbus/dbus-transport-socket.c(227):check_read_watch] setting read watch enabled = 1 2: 385: [dbus/dbus-sysdeps-win.c(400):_dbus_read_socket] recv: count=2048 fd=148 2: 385: [dbus/dbus-sysdeps-win.c(406):_dbus_read_socket] recv: failed: Resource temporarily unavailable (10035) 2: 385: [dbus/dbus-connection.c(1147):_dbus_connection_release_io_path] locking io_path_mutex 2: 385: [dbus/dbus-connection.c(1153):_dbus_connection_release_io_path] start connection->io_path_acquired = 1 2: 385: [dbus/dbus-connection.c(1158):_dbus_connection_release_io_path] unlocking io_path_mutex 2: 385: [dbus/dbus-connection.c(1515):_dbus_connection_handle_watch] middle 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(1522):_dbus_connection_handle_watch] end 2: 385: [dbus/dbus-sysdeps-win.c(1358):_dbus_poll] select: to=0 2: R:148 E:148 2: 2: [dbus/dbus-sysdeps-win.c(1388):_dbus_poll] select: = 0 2: 385: [bus/test.c(226):bus_test_run_clients_loop] ---> Done dispatching on "client side" 2: 385: [dbus/dbus-connection.c(4384):dbus_connection_get_dispatch_status] start 2: 385: [dbus/dbus-connection.c(4386):dbus_connection_get_dispatch_status] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(2979):dbus_connection_get_is_connected] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(4384):dbus_connection_get_dispatch_status] start 2: 385: [dbus/dbus-connection.c(4386):dbus_connection_get_dispatch_status] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(4096):dbus_connection_pop_message] start 2: 385: [dbus/dbus-connection.c(4384):dbus_connection_get_dispatch_status] start 2: 385: [dbus/dbus-connection.c(4386):dbus_connection_get_dispatch_status] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(4105):dbus_connection_pop_message] LOCK 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(4136):_dbus_connection_acquire_dispatch] locking dispatch_mutex 2: 385: [dbus/dbus-connection.c(4150):_dbus_connection_acquire_dispatch] unlocking dispatch_mutex 2: 385: [dbus/dbus-connection.c(4153):_dbus_connection_acquire_dispatch] LOCK 2: 385: [dbus/dbus-connection.c(4000):_dbus_connection_pop_message_link_unlocked] Message 00245018 (method_return no path no interface no member sig:'s' serial:1) removed from incoming queue 002469B8, 0 incoming 2: 385: [dbus/dbus-connection.c(4111):dbus_connection_pop_message] Returning popped message 00245018 2: 385: [dbus/dbus-connection.c(4169):_dbus_connection_release_dispatch] locking dispatch_mutex 2: 385: [dbus/dbus-connection.c(4177):_dbus_connection_release_dispatch] unlocking dispatch_mutex 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [bus/dispatch.c(640):verbose_message_received] Received message interface "(unset)" member "(unset)" error name "(unset)" on 002469B8 2: 385: [bus/dispatch.c(1013):check_hello_message] Got hello name: :1.0 2: 385: [dbus/dbus-dataslot.c(135):_dbus_data_slot_allocator_alloc] Allocated slot 1 on allocator 6DBE404C total 2 slots allocated 2 used 2: 385: [dbus/dbus-connection.c(4384):dbus_connection_get_dispatch_status] start 2: 385: [dbus/dbus-connection.c(4386):dbus_connection_get_dispatch_status] LOCK 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: 385: [dbus/dbus-connection.c(4096):dbus_connection_pop_message] start 2: 385: [dbus/dbus-connection.c(4384):dbus_connection_get_dispatch_status] start 2: 385: [dbus/dbus-connection.c(4386):dbus_connection_get_dispatch_status] LOCK 2: 385: [dbus/dbus-connection.c(4268):_dbus_connection_get_dispatch_status_unlocked] dispatch status = complete is_connected = 1 2: 385: [dbus/dbus-connection.c(406):_dbus_connection_unlock] UNLOCK 2: Expecting NameAcquired, got nothing 2: 385: [dbus/dbus-sysdeps-win.c(2680):_dbus_print_backtrace] D-Bus not compiled with backtrace support 2: S:\ralf\src\dbus-1-cmake-cross-x86-build\bin\test-bus.exe: Running expire list test 2: S:\ralf\src\dbus-1-cmake-cross-x86-build\bin\test-bus.exe: checking for memleaks 2: S:\ralf\src\dbus-1-cmake-cross-x86-build\bin\test-bus.exe: Running config file parser test 2: Testing retrieving the default session service directories 2: default service dir: S:/ralf/src/dbus-1-cmake-cross-x86-build/share/dbus-1/services 2: default service dir: C:\Program Files\Common Files/dbus-1/services 2: test service dir: 'S:/ralf/src/dbus-1-cmake-cross-x86-build/share/dbus-1/services' 2: current standard service dir: 'S:/ralf/src/dbus-1-cmake-cross-x86-build/share/dbus-1/services' 2: test service dir: 'C:\Program Files\Common Files/dbus-1/services' 2: current standard service dir: 'C:\Program Files\Common Files/dbus-1/services' 2: default system service dir skipped 2: Testing valid files: 2: forbidding.conf 2: system.conf 2: session.conf 2: systemd-activation.conf 2: multi-user.conf 2: check-own-rules.conf 2: Check name org.freedesktop: not allowed 2: Check name org.freedesktop.ManySystem: not allowed 2: Check name org.freedesktop.ManySystems: allowed 2: Check name org.freedesktop.ManySystems.foo: allowed 2: Check name org.freedesktop.ManySystems.foo.bar: allowed 2: Check name org.freedesktop.ManySystems2: not allowed 2: Check name org.freedesktop.ManySystems2.foo: not allowed 2: Check name org.freedesktop.ManySystems2.foo.bar: not allowed 2: entities.conf 2: incoming-limit.conf 2: finite-timeout.conf 2: many-rules.conf 2: basic.conf 2: debug-allow-all.conf 2: listen-unix-runtime.conf 2: debug-allow-all-sha1.conf 2: Testing invalid files: 2: badselinux-1.conf 2: circular-3.conf 2: circular-1.conf 2: truncated-file.conf 2: not-well-formed.conf 2: circular-2.conf 2: badselinux-2.conf 2: Comparing equivalent files: 2: entities-2.conf 2: entities-1.conf 2: Comparing equivalent files: 2: basic-1.conf 2: basic-2.conf 2: S:\ralf\src\dbus-1-cmake-cross-x86-build\bin\test-bus.exe: checking for memleaks 2: S:\ralf\src\dbus-1-cmake-cross-x86-build\bin\test-bus.exe: Running signals test 2: S:\ralf\src\dbus-1-cmake-cross-x86-build\bin\test-bus.exe: checking for memleaks 2: S:\ralf\src\dbus-1-cmake-cross-x86-build\bin\test-bus.exe: Running SHA1 connection test 1/1 Test #2: test-bus .........................***Failed 0.25 sec 0% tests passed, 1 tests failed out of 1 Total Test time (real) = 0.25 sec The following tests FAILED: 2 - test-bus (Failed)