kannel pam patch by Alejandro Guerrieri

Hi All!

I use the latest version of kannel, sqlbox and opensmppbox compiled with
--enable-pam option:

Kannel bearerbox version `svn-r4910'. Build `Jul 1 2011 07:34:05', compiler
`4.5.1 20100924 (Red Hat 4.5.1-4)'. System Linux, release
2.6.35.13-92.fc14.i686.
PAE, version #1 SMP Sat May 21 17:33:09 UTC 2011, machine i686. Hostname
****, IP 127.0.0.1. Libxml version 2.7.7. Using OpenSSL 1.0.0d-fips 8 Feb
2011. Comp
iled with MySQL 5.1.56, using MySQL 5.1.56. Using native malloc.

I use PAM (pam_radius) for opensmppbox and sendsms-user (username = pam,
password = dummy). All works fine for opensmppbox users but all
sendsms-users are lo
gged as 'pam' in sent_sms table (field service). So I decided to apply
Alejandro Guerrieri patch (http://www.blogalex.com/archives/206) to
distinguish between different users.

The problem is that after applying this patch only the first message (after
kannel start) is authenticated and sent successfully. All subsequent
messages fail with 'Authorization failed for sendsms'. RADIUS server debug
reveals that request to RADIUS is sent only for the first message.

Why this is happening? Any suggestion would be greatly appreciated.

The following data is from smsbox log file:

1) Kannel start

2011-07-01 09:43:39 [11530] [0] INFO: Added logfile
`/var/log/kannel/smsbox-pk.log' with level `0'.
2011-07-01 09:43:39 [11530] [0] INFO: HTTP: Opening server at port 13003.
2011-07-01 09:43:39 [11530] [0] DEBUG: Started thread 1
(gwlib/fdset.c:poller)
2011-07-01 09:43:39 [11530] [0] DEBUG: Started thread 2
(gwlib/http.c:server_thread)
2011-07-01 09:43:39 [11530] [0] INFO: Set up send sms service at port 13003
2011-07-01 09:43:39 [11530] [0] DEBUG: Started thread 3
(gw/smsbox.c:sendsms_thread)
2011-07-01 09:43:39 [11530] [1] DEBUG: Thread 1 (gwlib/fdset.c:poller) maps
to pid 11530.
2011-07-01 09:43:39 [11530] [0] DEBUG:
----------------------------------------------
2011-07-01 09:43:39 [11530] [0] DEBUG: Kannel smsbox version svn-r4910M
starting
2011-07-01 09:43:39 [11530] [2] DEBUG: Thread 2 (gwlib/http.c:server_thread)
maps to pid 11530.
2011-07-01 09:43:39 [11530] [2] DEBUG: HTTP: Including port 13003, fd 11 for
polling in server thread
2011-07-01 09:43:39 [11530] [0] DEBUG:   dumping group (sendsms-user):
2011-07-01 09:43:39 [11530] [3] DEBUG: Thread 3 (gw/smsbox.c:sendsms_thread)
maps to pid 11530.
2011-07-01 09:43:39 [11530] [0] DEBUG:     <name> = <test123>
2011-07-01 09:43:39 [11530] [0] DEBUG:     <group> = <sendsms-user>
2011-07-01 09:43:39 [11530] [0] DEBUG:     <username> = <test123>
2011-07-01 09:43:39 [11530] [0] DEBUG:     <password> = <test123>
2011-07-01 09:43:39 [11530] [0] DEBUG:   dumping group (sendsms-pam-user):
2011-07-01 09:43:39 [11530] [0] DEBUG:     <group> = <sendsms-pam-user>
2011-07-01 09:43:39 [11530] [0] DEBUG:     <acl> = <kannel>
2011-07-01 09:43:39 [11530] [0] DEBUG: Started thread 4
(gw/smsbox.c:obey_request_thread)
2011-07-01 09:43:39 [11530] [0] DEBUG: Started thread 5
(gw/smsbox.c:url_result_thread)
2011-07-01 09:43:39 [11530] [5] DEBUG: Thread 5
(gw/smsbox.c:url_result_thread) maps to pid 11530.
2011-07-01 09:43:39 [11530] [0] DEBUG: Started thread 6
(gw/smsbox.c:http_queue_thread)
2011-07-01 09:43:39 [11530] [4] DEBUG: Thread 4
(gw/smsbox.c:obey_request_thread) maps to pid 11530.
2011-07-01 09:43:39 [11530] [0] DEBUG: Connecting to <127.0.0.1>
2011-07-01 09:43:39 [11530] [0] INFO: Connected to bearerbox at 127.0.0.1
port 13005.
2011-07-01 09:43:39 [11530] [0] DEBUG: Started thread 7
(gw/heartbeat.c:heartbeat_thread)
2011-07-01 09:43:39 [11530] [6] DEBUG: Thread 6
(gw/smsbox.c:http_queue_thread) maps to pid 11530.
2011-07-01 09:43:39 [11530] [7] DEBUG: Thread 7
(gw/heartbeat.c:heartbeat_thread) maps to pid 1

2) Message N1 sent successfully

2011-07-01 09:44:03 [11530] [2] DEBUG: HTTP: Creating HTTPClient for
`10.0.0.136'.
2011-07-01 09:44:03 [11530] [2] DEBUG: HTTP: Created HTTPClient area
0x16299a20.
2011-07-01 09:44:03 [11530] [3] INFO: smsbox: Got HTTP request
</cgi-bin/sendsms> from <10.0.0.136>
2011-07-01 09:44:03 [11530] [3] INFO: Starting PAM for user: miranda
2011-07-01 09:44:03 [11530] [3] INFO: sendsms used by <miranda>
2011-07-01 09:44:03 [11530] [3] INFO: sendsms
sender:<kannel:miranda:miranda> (10.0.0.136) to:<380952126750> msg:<>
2011-07-01 09:44:03 [11530] [3] DEBUG: Stored UUID
255b87fc-17a4-49c3-89ce-b1121ae483b0
2011-07-01 09:44:03 [11530] [3] DEBUG: message length 0, sending 1 messages
2011-07-01 09:44:03 [11530] [3] DEBUG: Status: 202 Answer: <Sent.>
2011-07-01 09:44:03 [11530] [3] DEBUG: Delayed reply - wait for bearerbox
2011-07-01 09:44:03 [11530] [0] DEBUG: Got ACK (0) of
255b87fc-17a4-49c3-89ce-b1121ae483b0
2011-07-01 09:44:03 [11530] [0] DEBUG: HTTP: Resetting HTTPClient for
`10.0.0.136'.
2011-07-01 09:44:03 [11530] [2] DEBUG: HTTP: Creating HTTPClient for
`10.0.0.136'.
2011-07-01 09:44:03 [11530] [2] DEBUG: HTTP: Created HTTPClient area
0x16294ac0.
2011-07-01 09:44:03 [11530] [3] INFO: smsbox: Got HTTP request
</favicon.ico> from <10.0.0.136>
2011-07-01 09:44:03 [11530] [3] DEBUG: Status: 404 Answer: <Unknown
request.>
2011-07-01 09:44:03 [11530] [3] DEBUG: HTTP: Resetting HTTPClient for
`10.0.0.136'.
2011-07-01 09:44:09 [11530] [4] INFO: Starting delivery report <kannel> from
<miranda>
....
dlr skipped
...

3) Message N2 failed

2011-07-01 09:44:23 [11530] [3] INFO: smsbox: Got HTTP request
</cgi-bin/sendsms> from <10.0.0.136>
2011-07-01 09:44:23 [11530] [3] INFO: Starting PAM for user: miranda
2011-07-01 09:44:23 [11530] [3] WARNING: PAM auth failed for user: miranda
2011-07-01 09:44:23 [11530] [3] DEBUG: Status: 403 Answer: <Authorization
failed for sendsms>
2011-07-01 09:44:23 [11530] [3] DEBUG: HTTP: Resetting HTTPClient for
`10.0.0.136'.
2011-07-01 09:44:23 [11530] [3] INFO: smsbox: Got HTTP request
</favicon.ico> from <10.0.0.136>
2011-07-01 09:44:23 [11530] [3] DEBUG: Status: 404 Answer: <Unknown
request.>
2011-07-01 09:44:23 [11530] [3] DEBUG: HTTP: Resetting HTTPClient for
`10.0.0.136'.
2011-07-01 09:45:04 [11530] [1] DEBUG: HTTP: Destroying HTTPClient area
0x16294ac0.
2011-07-01 09:45:04 [11530] [1] DEBUG: HTTP: Destroying HTTPClient for
`10.0.0.136'.
2011-07-01 09:46:04 [11530] [1] DEBUG: Timeout for fd:25 appears.
2011-07-01 09:46:04 [11530] [1] DEBUG: HTTP: Destroying HTTPClient area
0x16299a20.
2011-07-01 09:46:04 [11530] [1] DEBUG: HTTP: Destroying HTTPClient for
`10.0.0.136'.

Best regards,
Miranda Weasley
ITProfStudio