smsbox and mutex detailed analysis

Benjamin Lee <[email protected]>
Newsgroups gmane.comp.mobile.kannel.devel
Message-ID <[email protected]> 
I'm not as familiar with the Kannel code as various others so I hope this can
help track down the mutex problem in smsbox.

To reproduce the mutex failure, you simply need to make rapid HTTP requests to
smsbox. Sometimes smsbox will kark it quickly, or sometimes it will take
longer. You can point bearerbox to a bad IP SMSC... so that the messages don't
actually get sent out.

This is where the mutex is failing...

2002-02-18 05:15:28 [3] PANIC: gwlib/conn.c:174: unlock_out_real: Mutex unlock failed. (Called from gwlib/conn.c:793:conn_register.)

My line numbers aren't in sync with CVS so I've attached a patch to insert the
debugging messages that I've coded.

It looks like the HTTP server thread [2] is doing something bad with the 'conn'
mutex because smsbox seems to die when the HTTP server thread [2] calls
conn_register before sendsms thread [3] calls conn_register.

Phew... I hope someone can manage to kill this bug with the info provided...
'cause my brain is highly overloaded with pthread-i-ness... ;-)

Good luck,
Cheerios,
Ben



2002-02-18 05:34:05 [0] INFO: Starting to log to file /home/ben/smsbox.log level 3
2002-02-18 05:34:05 [0] INFO: Added logfile `/home/ben/smsbox.log' with level `3'.
2002-02-18 05:34:05 [0] INFO: Service global sender set as '123'
2002-02-18 05:34:05 [0] DEBUG: HTTP: Opening server at port 13013.
2002-02-18 05:34:05 [0] DEBUG: Started thread 1 (gwlib/fdset.c:poller)
2002-02-18 05:34:05 [0] DEBUG: Started thread 2 (gwlib/http.c:server_thread)
2002-02-18 05:34:05 [0] INFO: Set up send sms service at port 13013
2002-02-18 05:34:05 [0] DEBUG: Started thread 3 (gw/smsbox.c:sendsms_thread)
2002-02-18 05:34:05 [0] DEBUG: ----------------------------------------------
2002-02-18 05:34:05 [0] DEBUG: Kannel smsbox version cvs starting
2002-02-18 05:34:05 [0] DEBUG: Started thread 4 (gw/smsbox.c:obey_request_thread)
2002-02-18 05:34:05 [0] DEBUG: Started thread 5 (gw/smsbox.c:url_result_thread)
2002-02-18 05:34:05 [0] INFO: Connected to bearerbox at localhost port 13001.
2002-02-18 05:34:05 [0] DEBUG: Started thread 6 (gw/heartbeat.c:heartbeat_thread)

<everything is normal here>

2002-02-18 05:37:12 [3] INFO: smsbox: Got HTTP request </cgi-bin/sendsms> from <192.168.1.149>
2002-02-18 05:37:12 [3] INFO: sendsms used by <dotwap>
2002-02-18 05:37:12 [3] INFO: sendsms sender:<dotwap:0416905132> (192.168.1.149) to:<61413122959> msg:<Accs Staff: There is training on today at the Pelly Bar from 5pm - 7pm, Davey St Frankston for all those interested.(Reminder 2 WEEKS NOTICE for any time off!!)>
2002-02-18 05:37:12 [3] DEBUG: message length 160, sending 1 messages
2002-02-18 05:37:12 [3] ERROR: ben unlock_out_real: conn_write_withlen: gwlib/conn.c:1012
2002-02-18 05:37:12 [3] DEBUG: Status: 202 Answer: <Sent.>
2002-02-18 05:37:12 [3] ERROR: ben unlock_out_real: conn_write: gwlib/conn.c:985
2002-02-18 05:37:12 [3] DEBUG: HTTP: Resetting HTTPClient for `192.168.1.149'.
2002-02-18 05:37:12 [3] DEBUG: ben ret == 0 client_reset(client): http_send_reply
2002-02-18 05:37:12 [3] ERROR: ben unlock_in_real: conn_register: gwlib/conn.c:793
2002-02-18 05:37:12 [3] ERROR: ben unlock_out_real: conn_register: gwlib/conn.c:794
2002-02-18 05:37:12 [1] ERROR: ben unlock_in_real: poll_callback: gwlib/conn.c:746
2002-02-18 05:37:12 [1] ERROR: ben unlock_in_real: conn_read_line: gwlib/conn.c:1072
2002-02-18 05:37:12 [1] ERROR: ben unlock_in_real: conn_eof: gwlib/conn.c:688
2002-02-18 05:37:12 [1] DEBUG: HTTP: Destroying HTTPClient area 0x809b628.
2002-02-18 05:37:12 [1] DEBUG: HTTP: Destroying HTTPClient for `192.168.1.149'.
2002-02-18 05:37:12 [2] DEBUG: HTTP: Creating HTTPClient for `192.168.1.149'.
2002-02-18 05:37:12 [2] ERROR: ben unlock_in_real: conn_register: gwlib/conn.c:793
2002-02-18 05:37:12 [2] ERROR: ben unlock_out_real: conn_register: gwlib/conn.c:794
2002-02-18 05:37:12 [1] ERROR: ben unlock_in_real: poll_callback: gwlib/conn.c:746
2002-02-18 05:37:12 [1] ERROR: ben unlock_in_real: conn_read_line: gwlib/conn.c:1089
2002-02-18 05:37:12 [1] ERROR: ben unlock_in_real: conn_read_line: gwlib/conn.c:1089
2002-02-18 05:37:12 [1] ERROR: ben unlock_in_real: conn_unregister: gwlib/conn.c:827
2002-02-18 05:37:12 [1] ERROR: ben unlock_out_real: conn_unregister: gwlib/conn.c:828
2002-02-18 05:37:12 [3] INFO: smsbox: Got HTTP request </cgi-bin/sendsms> from <192.168.1.149>
2002-02-18 05:37:12 [3] INFO: sendsms used by <dotwap>
2002-02-18 05:37:12 [3] INFO: sendsms sender:<dotwap:0416905132> (192.168.1.149) to:<61408493783> msg:<Accs Staff: There is training on today at the Pelly Bar from 5pm - 7pm, Davey St Frankston for all those interested.(Reminder 2 WEEKS NOTICE for any time off!!)>
2002-02-18 05:37:12 [3] DEBUG: message length 160, sending 1 messages
2002-02-18 05:37:12 [3] ERROR: ben unlock_out_real: conn_write_withlen: gwlib/conn.c:1012
2002-02-18 05:37:12 [3] DEBUG: Status: 202 Answer: <Sent.>
2002-02-18 05:37:12 [3] ERROR: ben unlock_out_real: conn_write: gwlib/conn.c:985
2002-02-18 05:37:12 [3] DEBUG: HTTP: Resetting HTTPClient for `192.168.1.149'.
2002-02-18 05:37:12 [3] DEBUG: ben ret == 0 client_reset(client): http_send_reply
2002-02-18 05:37:12 [3] ERROR: ben unlock_in_real: conn_register: gwlib/conn.c:793
2002-02-18 05:37:12 [3] ERROR: ben unlock_out_real: conn_register: gwlib/conn.c:794
2002-02-18 05:37:12 [1] ERROR: ben unlock_in_real: poll_callback: gwlib/conn.c:746
2002-02-18 05:37:12 [1] ERROR: ben unlock_in_real: conn_read_line: gwlib/conn.c:1072
2002-02-18 05:37:12 [1] ERROR: ben unlock_in_real: conn_eof: gwlib/conn.c:688
2002-02-18 05:37:12 [1] DEBUG: HTTP: Destroying HTTPClient area 0x809af48.
2002-02-18 05:37:12 [1] DEBUG: HTTP: Destroying HTTPClient for `192.168.1.149'.
2002-02-18 05:37:12 [2] DEBUG: HTTP: Creating HTTPClient for `192.168.1.149'.
2002-02-18 05:37:12 [2] ERROR: ben unlock_in_real: conn_register: gwlib/conn.c:793
2002-02-18 05:37:12 [2] ERROR: ben unlock_out_real: conn_register: gwlib/conn.c:794
2002-02-18 05:37:12 [1] ERROR: ben unlock_in_real: poll_callback: gwlib/conn.c:746
2002-02-18 05:37:12 [1] ERROR: ben unlock_in_real: conn_read_line: gwlib/conn.c:1089
2002-02-18 05:37:12 [1] ERROR: ben unlock_in_real: conn_read_line: gwlib/conn.c:1089
2002-02-18 05:37:12 [1] ERROR: ben unlock_in_real: conn_unregister: gwlib/conn.c:827
2002-02-18 05:37:12 [1] ERROR: ben unlock_out_real: conn_unregister: gwlib/conn.c:828
2002-02-18 05:37:12 [3] INFO: smsbox: Got HTTP request </cgi-bin/sendsms> from <192.168.1.149>
2002-02-18 05:37:12 [3] INFO: sendsms used by <dotwap>
2002-02-18 05:37:12 [3] INFO: sendsms sender:<dotwap:0416905132> (192.168.1.149) to:<61412007793> msg:<Accs Staff: There is training on today at the Pelly Bar from 5pm - 7pm, Davey St Frankston for all those interested.(Reminder 2 WEEKS NOTICE for any time off!!)>
2002-02-18 05:37:12 [3] DEBUG: message length 160, sending 1 messages
2002-02-18 05:37:12 [3] ERROR: ben unlock_out_real: conn_write_withlen: gwlib/conn.c:1012
2002-02-18 05:37:12 [3] DEBUG: Status: 202 Answer: <Sent.>
2002-02-18 05:37:12 [3] ERROR: ben unlock_out_real: conn_write: gwlib/conn.c:985
2002-02-18 05:37:12 [3] DEBUG: HTTP: Resetting HTTPClient for `192.168.1.149'.
2002-02-18 05:37:12 [3] DEBUG: ben ret == 0 client_reset(client): http_send_reply
2002-02-18 05:37:12 [2] DEBUG: HTTP: Creating HTTPClient for `192.168.1.149'.
2002-02-18 05:37:12 [2] ERROR: ben unlock_in_real: conn_register: gwlib/conn.c:793
2002-02-18 05:37:12 [2] ERROR: ben unlock_out_real: conn_register: gwlib/conn.c:794
2002-02-18 05:37:12 [3] ERROR: ben unlock_in_real: conn_register: gwlib/conn.c:793
2002-02-18 05:37:12 [1] ERROR: ben unlock_in_real: poll_callback: gwlib/conn.c:746
2002-02-18 05:37:12 [1] ERROR: ben unlock_in_real: conn_read_line: gwlib/conn.c:1072
2002-02-18 05:37:12 [1] ERROR: ben unlock_in_real: conn_eof: gwlib/conn.c:688
2002-02-18 05:37:12 [1] DEBUG: HTTP: Destroying HTTPClient area 0x8099928.
2002-02-18 05:37:12 [1] DEBUG: HTTP: Destroying HTTPClient for `192.168.1.149'.
2002-02-18 05:37:12 [3] ERROR: ben unlock_out_real: conn_register: gwlib/conn.c:794
2002-02-18 05:37:12 [3] DEBUG: ben mutex_unlock_real EINVAL
2002-02-18 05:37:12 [3] ERROR: gwlib/thread.c:107: mutex_unlock_real: Mutex failure! (Called from gwlib/conn.c:171:unlock_out_real.)
2002-02-18 05:37:12 [3] PANIC: gwlib/conn.c:174: unlock_out_real: Mutex unlock failed. (Called from gwlib/conn.c:794:conn_register.)


-- 
Benjamin Lee

71-75 City Rd, South Melbourne, VIC 3006 Australia  http://www.dotwap.com/
Phone +61 3 9698 1840  Mobile +61 414 717 573  Fax +61 3 9698 1841
mutex-debug-only.patch (text/plain, 4.8 KB) 
Index: Makefile.in
===================================================================
RCS file: /home/cvs/gateway/Makefile.in,v
retrieving revision 1.56
diff -u -r1.56 Makefile.in
--- Makefile.in	2002/01/23 18:33:00	1.56
+++ Makefile.in	2002/02/18 21:45:32
@@ -228,12 +228,12 @@
 dummy:
 
 install: all
-	$(INSTALL) -d $(bindir)
+	$(INSTALL) -d $(DESTDIR)$(bindir)
 	for prog in $(binprogs); do \
 		$(INSTALL) $$prog \
 		    $(DESTDIR)$(bindir)/`basename $$prog`$(suffix); \
 	done
-	$(INSTALL) -d $(sbindir)
+	$(INSTALL) -d $(DESTDIR)$(sbindir)
 	for prog in $(sbinprogs); do \
 		$(INSTALL) $$prog \
 		    $(DESTDIR)$(sbindir)/`basename $$prog`$(suffix); \
Index: gw/smsbox.c
===================================================================
RCS file: /home/cvs/gateway/gw/smsbox.c,v
retrieving revision 1.170
diff -u -r1.170 smsbox.c
--- gw/smsbox.c	2002/02/07 22:16:35	1.170
+++ gw/smsbox.c	2002/02/18 21:45:33
@@ -1791,6 +1791,8 @@
     }
 
     http_destroy_headers(reply_hdrs);
+    
+    debug("sms.http", 0, "ben %s", __func__);
 }
 
 
Index: gwlib/conn.c
===================================================================
RCS file: /home/cvs/gateway/gwlib/conn.c,v
retrieving revision 1.48
diff -u -r1.48 conn.c
--- gwlib/conn.c	2002/01/29 00:14:42	1.48
+++ gwlib/conn.c	2002/02/18 21:45:33
@@ -105,9 +105,24 @@
  * unlocked_try_write. */
 
 /* Macros to get more information for debugging purposes */
-#define unlock_in(conn) unlock_in_real(conn, __FILE__, __LINE__, __func__)
-#define unlock_out(conn) unlock_out_real(conn, __FILE__, __LINE__, __func__)
+#define unlock_in(conn) error(0, "ben unlock_in_real: %s: %s:%d", \
+				__func__, __FILE__, __LINE__); \
+unlock_in_real(conn, __FILE__, __LINE__, __func__)
 
+
+
+#define unlock_out(conn) error(0, "ben unlock_out_real: %s: %s:%d", \
+				__func__, __FILE__, __LINE__); \
+unlock_out_real(conn, __FILE__, __LINE__, __func__)
+
+
+// #define lock_out(conn) error(0, "ben lock_out_real: %s: %s:%d", \
+// 				__func__, __FILE__, __LINE__); \
+// lock_out(conn)
+
+
+
+	
 /* Lock a Connection's read direction, if the Connection is unclaimed */
 static void lock_in(Connection *conn)
 {
@@ -719,6 +734,7 @@
         unlocked_write(conn);
 	if (unlocked_outbuf_len(conn) == 0)
 	    do_callback = 1;
+        debug("sms.conn", 0, "ben unlocked_outbuf_len(conn) == 0: %s", __func__);    
         unlock_out(conn);
     }
 
@@ -775,7 +791,15 @@
     }
 
     unlock_in(conn);
-    unlock_out(conn);
+    unlock_out(conn);       /* OH YEAH BABY, THIS IS WHERE THE SHIT FALLS APART! */
+    
+/*
+ * 2002-02-18 03:54:51 [3] ERROR: ben unlock_out_real: conn_register: gwlib/conn.c:793
+ * 2002-02-18 03:54:51 [3] DEBUG: ben mutex_unlock_real EINVAL
+ * 2002-02-18 03:54:51 [3] ERROR: gwlib/thread.c:107: mutex_unlock_real: Mutex failure! (Called from gwlib/conn.c:171:unlock_out_real.)
+ * 2002-02-18 03:54:51 [3] PANIC: gwlib/conn.c:174: unlock_out_real: Mutex unlock failed. (Called from gwlib/conn.c:793:conn_register.)
+ */
+   
 
     return result;
 }
Index: gwlib/http.c
===================================================================
RCS file: /home/cvs/gateway/gwlib/http.c,v
retrieving revision 1.159
diff -u -r1.159 http.c
--- gwlib/http.c	2002/01/18 18:35:21	1.159
+++ gwlib/http.c	2002/02/18 21:45:33
@@ -1974,15 +1974,19 @@
     octstr_destroy(response);
 
     if (ret == 0) {	/* Sent already */
-	if (!client->persistent_conn)
+	if (!client->persistent_conn) {
+        debug("sms.http", 0, "ben client_destroy persistent_conn: %s", __func__);
 	    client_destroy(client);
+    }
 	else {
 	    client_reset(client);
+        debug("sms.http", 0, "ben ret == 0 client_reset(client): %s", __func__);
 	    conn_register(client->conn, server_fdset, receive_request, client);
 	}
     }
     else if (ret == 1) {      /* Queued for sending, we don't want to block */
 	client->state = sending_reply;
+        debug("sms.http", 0, "ben ret == 1 client->state = sending_reply: %s", __func__);
 	conn_register(client->conn, server_fdset, receive_request, client);
     }
     else	/* Error */
Index: gwlib/thread.c
===================================================================
RCS file: /home/cvs/gateway/gwlib/thread.c,v
retrieving revision 1.34
diff -u -r1.34 thread.c
--- gwlib/thread.c	2002/01/29 00:30:06	1.34
+++ gwlib/thread.c	2002/02/18 21:45:33
@@ -95,8 +95,15 @@
     gw_assert(mutex != NULL);
     mutex->owner = -1;
     ret = pthread_mutex_unlock(&mutex->mutex);
+    
+    if ( ret == EPERM ) {
+        debug("gwlib.http", 0, "ben %s EPERM", __func__);
+    } else if ( ret == EINVAL ) {
+        debug("gwlib.http", 0, "ben %s EINVAL", __func__);
+    }
+    
     if (ret != 0)
-        panic(0, "%s:%ld: %s: Mutex failure! (Called from %s:%ld:%s.)", \
+        error(0, "%s:%ld: %s: Mutex failure! (Called from %s:%ld:%s.)", \
 		         __FILE__, (long) __LINE__, __func__, file, (long) line, func);
 
     return ret;
lmpx.com only provides a reader for public news (NNTP) servers. It is not affiliated with the servers or forums shown here and is not responsible for the content of articles, which is written by their respective authors.