View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0002283GNUnettransport servicepublic2012-04-23 12:052012-06-02 19:15
ReporterLRN Assigned ToMatthias Wachs  
PriorityurgentSeveritycrashReproducibilityalways
Status closedResolutionfixed 
Product VersionGit master 
Target Version0.9.3 
Summary0002283: Crash in transport service during test_testing
Descriptionr21105+8
Additional Information
Reading symbols from d:\progs\gnunet\bin\gnunet-service-transport.exe...done.
[Switching to Thread 9976.0x18bc]
(gdb) thread 1
[Switching to thread 1 (Thread 9976.0x28e8)]
#0  0x7794f8b1 in ntdll!RtlUpdateClonedSRWLock () from C:\Windows\SysWOW64\ntdll.dll
(gdb) bt
#0  0x7794f8b1 in ntdll!RtlUpdateClonedSRWLock () from C:\Windows\SysWOW64\ntdll.dll
#1  0x7794f8b1 in ntdll!RtlUpdateClonedSRWLock () from C:\Windows\SysWOW64\ntdll.dll
#2  0x76b20a91 in WaitForSingleObjectEx () from C:\Windows\syswow64\KernelBase.dll
#3  0x000002b0 in ?? ()
#4  0x00000000 in ?? ()
(gdb) c
Continuing.

Program received signal SIGSEGV, Segmentation fault.
0x00405baa in _fu197__skip_log () at gnunet-service-transport_clients.c:355
355       msize = ntohs (msg->size);
(gdb) bt
#0  0x00405baa in _fu197__skip_log () at gnunet-service-transport_clients.c:355
#1  0x00406b45 in _fu248__skip_log () at gnunet-service-transport_clients.c:504
#2  0x61c38f93 in GNUNET_SERVER_inject (server=0x1d7f200, sender=0x48ec20, message=0x27fc00) at server.c:866
#3  0x61c39a46 in client_message_tokenizer_callback (cls=0x1d7f200, client=0x48ec20, message=0x27fc00) at server.c:1071
#4  0x61c3b5e2 in GNUNET_SERVER_mst_receive (mst=0x1d8dbb8, client_identity=0x48ec20, buf=0x27fc00 "", size=72, purge=0, one_shot=-1) at server_mst.c:264
#5  0x61c397cc in process_incoming (cls=0x48ec20, buf=0x27fc00, available=72, addr=0x48a7d8, addrlen=28, errCode=0) at server.c:1014
#6  0x61c0e05a in receive_ready (cls=0x1d849a8, tc=0x28fc90) at connection.c:1054
#7  0x61c35986 in run_ready (rs=0x1d95240, ws=0x1d96270) at scheduler.c:602
#8  0x61c360f7 in GNUNET_SCHEDULER_run (task=0x61c410e9 <service_task>, task_cls=0x28fe28) at scheduler.c:790
#9  0x61c41dcb in GNUNET_SERVICE_run (argc=3, argv=0x1d7a3c0, service_name=0x41736b "transport", options=GNUNET_SERVICE_OPTION_SOFT_SHUTDOWN, task=0x40257a <run>, task_cls=0x0) at service.c:1774
#10 0x004028f7 in main (argc=3, argv=0x1d7a3c0) at gnunet-service-transport.c:644
(gdb) p msg
$1 = (const struct GNUNET_MessageHeader *) 0x0
(gdb) up
#1  0x00406b45 in _fu248__skip_log () at gnunet-service-transport_clients.c:504
504       unicast (tc, GST_hello_get (), GNUNET_NO);
(gdb) p our_hello
$2 = (struct GNUNET_HELLO_Message *) 0x0
TagsNo tags attached.

Activities

LRN

2012-04-23 12:49

reporter   ~0005732

Here's a piece of log:
00000000000520247149 util-7412 INFO Accepting connection from `[::1]:62715': 0x1e24398
00000000000520247149 util-7412 DEBUG Server accepted incoming connection.
00000000000520247149 util-scheduler-7412 DEBUG Adding task: 24 / 0x1e24398
...
00000000000520247149 util-scheduler-7412 DEBUG Running task: 12 / 0x1e264c0
00000000000520247150 util-scheduler-7412 DEBUG Adding task: 26 / 0x1e264c0
00000000000520247150 util-scheduler-7412 DEBUG Running task: 22 / 0x6ad118
00000000000520247150 util-7412 DEBUG `parent_control_handler' invoked because of 17
00000000000520247150 util-scheduler-7412 DEBUG Running task: 23 / 0x1e24260
00000000000520247150 util-scheduler-7412 DEBUG Adding task: 27 / 0x1e24260
00000000000520247150 util-scheduler-7412 DEBUG Running task: 24 / 0x1e24398
00000000000520247150 util-scheduler-7412 DEBUG Adding task: 28 / 0x1e24398
00000000000520247150 util-scheduler-7412 DEBUG Running task: 25 / 0x1e10548
00000000000520247150 util-scheduler-7412 DEBUG Adding task: 29 / 0x1e10548
00000000000520247150 util-scheduler-7412 DEBUG Running task: 18 / 0x1e2edd8
...
00000000000520247150 tcp-7412 DEBUG Shutting down TCP plugin
00000000000520247150 util-7412 DEBUG Server shutting down.
00000000000520247150 util-scheduler-7412 DEBUG Canceling task: 26 / 0x1e264c0
00000000000520247150 util-7412 DEBUG Closed 0x2a4, closesocket() returned 0, GLE is 0
00000000000520247150 util-scheduler-7412 DEBUG Canceling task: 13 / 0x1e105f8
00000000000520247150 util-scheduler-7412 DEBUG Canceling task: 14 / 0x1e105f8
00000000000520247150 util-scheduler-7412 DEBUG Canceling task: 31 / 0x1e22b08
00000000000520247150 util-scheduler-7412 DEBUG Canceling task: 9 / 0x1e22b08
00000000000520247150 util-7412 DEBUG Asked to destroy notification context 0x6ad538
00000000000520247150 util-scheduler-7412 DEBUG Canceling task: 8 / 0x0
00000000000520247150 transport-7412 DEBUG Freeing our HELLO
00000000000520247150 util-7412 DEBUG Shutting down connection (0x1e0f6b0)
00000000000520247150 util-scheduler-7412 DEBUG Canceling task: 6 / 0x1e10370
00000000000520247150 util-scheduler-7412 DEBUG Canceling task: 16 / 0x1e106d8
00000000000520247150 util-7412 DEBUG Shutting down connection (0x1e106d8)
00000000000520247150 util-scheduler-7412 DEBUG Canceling task: 15 / 0x1e10780
00000000000520247150 util-scheduler-7412 DEBUG Running task: 5 / 0x28fe28
00000000000520247150 util-7412 DEBUG Server in soft shutdown
00000000000520247150 util-scheduler-7412 DEBUG Canceling task: 29 / 0x1e10548
00000000000520247150 util-7412 DEBUG Closed 0x8, closesocket() returned 0, GLE is 0
00000000000520247150 util-7412 DEBUG Closed 0xc, closesocket() returned 0, GLE is 0
00000000000520247151 util-scheduler-7412 DEBUG Running task: 20 / 0x1e24128
00000000000520247151 util-scheduler-7412 DEBUG Adding task: 32 / 0x1e24128
00000000000520247151 util-7412 DEBUG FD 0x1c4 (0x6a95a8) is SET in rfds
00000000000520247151 util-7412 DEBUG Reading 0 bytes from the pipe 0x1c4
00000000000520247151 util-7412 DEBUG Adding the pipe's 0x1c4 overlapped event to the array as 0
00000000000520247151 util-7412 DEBUG Adding the socket read event to the array as 1
00000000000520247151 util-7412 DEBUG Adding the socket write event to the array as 2
00000000000520247151 util-7412 DEBUG Number nfds: 701, handles: 3, return code: 0 will wait: -1 ms
00000000000520247151 util-7412 DEBUG WaitForMultipleObjects Returned : 1
00000000000520247151 util-7412 DEBUG return pos is : 1
00000000000520247151 util-7412 DEBUG Select retcode : 3
00000000000520247151 util-7412 DEBUG ReadPipes is : 1
00000000000520247151 util-7412 DEBUG Wait for the write event returned 258
00000000000520247151 util-7412 DEBUG Zeroing rfds
00000000000520247151 util-7412 DEBUG Zeroing wfds
00000000000520247151 util-7412 DEBUG FD 0x2b4 is SET in rfds
00000000000520247151 util-7412 DEBUG FD 0x2bc is SET in rfds
00000000000520247151 util-7412 DEBUG FD 0x2b8 is NOT SET in rfds
00000000000520247151 util-7412 DEBUG Returning 3 or 0
00000000000520247151 util-scheduler-7412 DEBUG Checking readiness of task: 32 / 0x1e24128
00000000000520247151 util-scheduler-7412 DEBUG Checking readiness of task: 28 / 0x1e24398
00000000000520247151 util-scheduler-7412 DEBUG Checking readiness of task: 27 / 0x1e24260
00000000000520247151 util-scheduler-7412 DEBUG Running task: 27 / 0x1e24260
00000000000520247151 util-7412 DEBUG receive_ready read 0/65535 bytes from `127.0.0.1:62716' (0x1e24260)!
00000000000520247151 util-7412 DEBUG Client is being disconnected from the server.
00000000000520247151 util-7412 DEBUG Shutting down connection (0x1e24260)
00000000000520247151 util-7412 DEBUG Closed 0x2b8, closesocket() returned 0, GLE is 0
00000000000520247151 util-scheduler-7412 DEBUG Running task: 28 / 0x1e24398
00000000000520247151 util-7412 DEBUG receive_ready read 72/65535 bytes from `[::1]:62715' (0x1e24398)!
00000000000520247151 util-7412 DEBUG Server receives 72 bytes from `[::1]:62715'.
00000000000520247151 util-7412 DEBUG Server-mst receives 72 bytes with 0 bytes already in private buffer
00000000000520247151 util-7412 DEBUG Server-mst has 72 bytes left in inbound buffer
00000000000520247151 util-7412 DEBUG Tokenizer gives server message of type 360 from client
00000000000520247151 util-7412 DEBUG Server schedules transmission of 72-byte message of type 360 to client.
00000000000520247151 util-scheduler-7412 DEBUG Adding task: 33 / 0x1e107f0
00000000000520247151 transport-7412 DEBUG Client 0x0 sent START
00000000000520247151 transport-7412 DEBUG Client 0x6a9598 connected

I.e. a client connects shortly before transport shuts down, and AFTER shutting down the transport receives a message from that client, tries to process it - and fails, because our_hello is freed by that point.

Matthias Wachs

2012-04-24 14:46

reporter   ~0005737

Added additional checks in 21129 + return if HELLO is null

Matthias Wachs

2012-04-24 18:03

reporter   ~0005738

transport receives client_start messages after all subsystems are shutdown.
Setting service option from
GNUNET_SERVICE_OPTION_SOFT_SHUTDOWN
to
GNUNET_SERVICE_OPTION_NONE

Issue History

Date Modified Username Field Change
2012-04-23 12:05 LRN New Issue
2012-04-23 12:05 LRN Status new => assigned
2012-04-23 12:05 LRN Assigned To => Matthias Wachs
2012-04-23 12:49 LRN Note Added: 0005732
2012-04-23 18:02 Christian Grothoff Priority normal => urgent
2012-04-23 18:02 Christian Grothoff Severity minor => crash
2012-04-23 18:02 Christian Grothoff Target Version => 0.9.3
2012-04-24 14:46 Matthias Wachs Note Added: 0005737
2012-04-24 14:47 Matthias Wachs Status assigned => resolved
2012-04-24 14:47 Matthias Wachs Resolution open => fixed
2012-04-24 18:03 Matthias Wachs Note Added: 0005738
2012-06-02 19:15 Christian Grothoff Status resolved => closed