Ok. I've checked the connections (I've got 2 tcp connections by smpp service
type so I've got 3 service types).
The problem started this morning, again, with service type associated to user
'kannel_c' , so I restarted the boxes and the queued messages were sent.
Now the problem It's happening again with service type associated to user
'kannel_a' and I can see all 6 tcp connections as ESTABLISHED.
The first PDU in smsbox-file.log, shows the problem Got ACK (3) of xxxxxx
The second PDU in smsbox-file.log, shows a previous message successfully sent
so it shows Got ACK (0) of yyyy and then shows the DLR part of the process.
In the meantime (while I'm writing this e-mail) the problem stopped without my
intervention and apparently 2 of the tcp connections to smsc changed the
initial tcp port.
So I think a tcp reconnection was made by the system to the smsc.
So, the question would be, where can I configurate a quick reconnection to smsc
of the service type that starts to show the "queued for later delivery" problem?
Regards,
Rodrigo
2006-12-04 17:15:13 [17124] [2] DEBUG: HTTP: Creating HTTPClient for
`127.0.0.1'.
2006-12-04 17:15:13 [17124] [2] DEBUG: HTTP: Created HTTPClient area 0x642170.
2006-12-04 17:15:13 [17124] [3] INFO: smsbox: Got HTTP request
</cgi-bin/sendsms> from <127.0.0.1>
2006-12-04 17:15:13 [17124] [3] INFO: sendsms used by <kannel_a>
2006-12-04 17:15:13 [17124] [3] INFO: sendsms sender:<kannel_a:3686>
(127.0.0.1) to:<88615688> msg:<xxxx>
2006-12-04 17:15:13 [17124] [3] DEBUG: Stored UUID
a3dd84be-e866-4575-b0ff-d77e78f26532
2006-12-04 17:15:13 [17124] [3] DEBUG: Octet string at 0x640710:
2006-12-04 17:15:13 [17124] [3] DEBUG: len: 40
2006-12-04 17:15:13 [17124] [3] DEBUG: size: 41
2006-12-04 17:15:13 [17124] [3] DEBUG: immutable: 0
2006-12-04 17:15:13 [17124] [3] DEBUG: data: 53 72 2e 20 75 73 75 61 72 69 6f
3a 0a 20 53 75 xxxx
2006-12-04 17:15:13 [17124] [3] DEBUG: data: 20 66 6f 74 6f 20 68 61 20 73 69
64 6f 20 70 75 yyyy
2006-12-04 17:15:13 [17124] [3] DEBUG: data: 62 6c 69 63 61 64 61 2e
zzzzz
2006-12-04 17:15:13 [17124] [3] DEBUG: Octet string dump ends.
2006-12-04 17:15:13 [17124] [3] DEBUG: Octet string at 0x640780:
2006-12-04 17:15:13 [17124] [3] DEBUG: len: 40
2006-12-04 17:15:13 [17124] [3] DEBUG: size: 1024
2006-12-04 17:15:13 [17124] [3] DEBUG: immutable: 0
2006-12-04 17:15:13 [17124] [3] DEBUG: data: 53 72 2e 20 75 73 75 61 72 69 6f
3a 0a 20 53 75 xxxx
2006-12-04 17:15:13 [17124] [3] DEBUG: data: 20 66 6f 74 6f 20 68 61 20 73 69
64 6f 20 70 75 yyyy
2006-12-04 17:15:13 [17124] [3] DEBUG: data: 62 6c 69 63 61 64 61 2e
zzzzz
2006-12-04 17:15:13 [17124] [3] DEBUG: Octet string at 0x6445f0:
2006-12-04 17:15:13 [17124] [3] DEBUG: len: 40
2006-12-04 17:15:13 [17124] [3] DEBUG: size: 41
2006-12-04 17:15:13 [17124] [3] DEBUG: immutable: 0
2006-12-04 17:15:13 [17124] [3] DEBUG: data: 53 72 2e 20 75 73 75 61 72 69 6f
3a 0a 20 53 75 xxxx
2006-12-04 17:15:13 [17124] [3] DEBUG: data: 20 66 6f 74 6f 20 68 61 20 73 69
64 6f 20 70 75 yyyy
2006-12-04 17:15:13 [17124] [3] DEBUG: data: 62 6c 69 63 61 64 61 2e
zzzz
2006-12-04 17:15:13 [17124] [3] DEBUG: Octet string dump ends.
2006-12-04 17:15:13 [17124] [3] DEBUG: Octet string at 0x644730:
2006-12-04 17:15:13 [17124] [3] DEBUG: len: 40
2006-12-04 17:15:13 [17124] [3] DEBUG: size: 1024
2006-12-04 17:15:13 [17124] [3] DEBUG: immutable: 0
2006-12-04 17:15:13 [17124] [3] DEBUG: data: 53 72 2e 20 75 73 75 61 72 69 6f
3a 0a 20 53 75 xxxx
2006-12-04 17:15:13 [17124] [3] DEBUG: data: 20 66 6f 74 6f 20 68 61 20 73 69
64 6f 20 70 75 yyyy
2006-12-04 17:15:13 [17124] [3] DEBUG: data: 62 6c 69 63 61 64 61 2e
zzzz
2006-12-04 17:15:13 [17124] [3] DEBUG: Octet string dump ends.
2006-12-04 17:15:13 [17124] [3] DEBUG: message length 40, sending 1 messages
2006-12-04 17:15:13 [17124] [3] DEBUG: Status: 202 Answer: <Sent.>
2006-12-04 17:15:13 [17124] [3] DEBUG: Delayed reply - wait for bearerbox
2006-12-04 17:15:13 [17124] [0] DEBUG: Got ACK (3) of
a3dd84be-e866-4575-b0ff-d77e78f26532 <-------------------------------
2006-12-04 17:15:13 [17124] [0] DEBUG: HTTP: Resetting HTTPClient for
`127.0.0.1'.
2006-12-04 17:15:13 [17124] [1] DEBUG: HTTP: Destroying HTTPClient area
0x642170.
2006-12-04 17:15:13 [17124] [1] DEBUG: HTTP: Destroying HTTPClient for
`127.0.0.1'.
2006-12-04 17:15:13 [17124] [3] DEBUG: Octet string dump ends.
2006-12-04 12:51:18 [31491] [2] DEBUG: HTTP: Creating HTTPClient for
`127.0.0.1'.
2006-12-04 12:51:18 [31491] [2] DEBUG: HTTP: Created HTTPClient area 0x6446a0.
2006-12-04 12:51:18 [31491] [3] INFO: smsbox: Got HTTP request
</cgi-bin/sendsms> from <127.0.0.1>
2006-12-04 12:51:18 [31491] [3] INFO: sendsms used by <kannel_a>
2006-12-04 12:51:18 [31491] [3] INFO: sendsms sender:<kannel_a:3686>
(127.0.0.1) to:<83384401> msg:<xxxxxxxx>
2006-12-04 12:51:18 [31491] [3] DEBUG: Stored UUID
79e9211b-14cb-4bf5-8a66-686cce9f005f
2006-12-04 12:51:18 [31491] [3] DEBUG: Octet string at 0x6545d0:
2006-12-04 12:51:18 [31491] [3] DEBUG: len: 40
2006-12-04 12:51:18 [31491] [3] DEBUG: size: 41
2006-12-04 12:51:18 [31491] [3] DEBUG: immutable: 0
2006-12-04 12:51:18 [31491] [3] DEBUG: data: 53 72 2e 20 75 73 75 61 72 69 6f
3a 0a 20 53 75 xxxx
2006-12-04 12:51:18 [31491] [3] DEBUG: data: 20 66 6f 74 6f 20 68 61 20 73 69
64 6f 20 70 75 yyyy
2006-12-04 12:51:18 [31491] [3] DEBUG: data: 62 6c 69 63 61 64 61 2e
zzzz
2006-12-04 12:51:18 [31491] [3] DEBUG: Octet string dump ends.
2006-12-04 12:51:18 [31491] [3] DEBUG: Octet string at 0x654640:
2006-12-04 12:51:18 [31491] [3] DEBUG: len: 40
2006-12-04 12:51:18 [31491] [3] DEBUG: size: 1024
2006-12-04 12:51:18 [31491] [3] DEBUG: immutable: 0
2006-12-04 12:51:18 [31491] [3] DEBUG: data: 53 72 2e 20 75 73 75 61 72 69 6f
3a 0a 20 53 75 xxxx
2006-12-04 12:51:18 [31491] [3] DEBUG: data: 20 66 6f 74 6f 20 68 61 20 73 69
64 6f 20 70 75 yyyy
2006-12-04 12:51:18 [31491] [3] DEBUG: data: 62 6c 69 63 61 64 61 2e
zzzz
2006-12-04 12:51:18 [31491] [3] DEBUG: Octet string dump ends.
2006-12-04 12:51:18 [31491] [3] DEBUG: Octet string at 0x63dfb0:
2006-12-04 12:51:18 [31491] [3] DEBUG: len: 40
2006-12-04 12:51:18 [31491] [3] DEBUG: size: 41
2006-12-04 12:51:18 [31491] [3] DEBUG: immutable: 0
2006-12-04 12:51:18 [31491] [3] DEBUG: data: 53 72 2e 20 75 73 75 61 72 69 6f
3a 0a 20 53 75 xxxx
2006-12-04 12:51:18 [31491] [3] DEBUG: data: 20 66 6f 74 6f 20 68 61 20 73 69
64 6f 20 70 75 yyyy
2006-12-04 12:51:18 [31491] [3] DEBUG: data: 62 6c 69 63 61 64 61 2e
zzzz
2006-12-04 12:51:18 [31491] [3] DEBUG: Octet string dump ends.
2006-12-04 12:51:18 [31491] [3] DEBUG: Octet string at 0x63e180:
2006-12-04 12:51:18 [31491] [3] DEBUG: len: 40
2006-12-04 12:51:18 [31491] [3] DEBUG: size: 1024
2006-12-04 12:51:18 [31491] [3] DEBUG: immutable: 0
2006-12-04 12:51:18 [31491] [3] DEBUG: data: 53 72 2e 20 75 73 75 61 72 69 6f
3a 0a 20 53 75 xxxx
2006-12-04 12:51:18 [31491] [3] DEBUG: data: 20 66 6f 74 6f 20 68 61 20 73 69
64 6f 20 70 75 yyyy
2006-12-04 12:51:18 [31491] [3] DEBUG: data: 62 6c 69 63 61 64 61 2e
zzzzz
2006-12-04 12:51:18 [31491] [3] DEBUG: Octet string dump ends.
2006-12-04 12:51:18 [31491] [3] DEBUG: message length 40, sending 1 messages
2006-12-04 12:51:18 [31491] [3] DEBUG: Status: 202 Answer: <Sent.>
2006-12-04 12:51:18 [31491] [3] DEBUG: Delayed reply - wait for bearerbox
2006-12-04 12:51:18 [31491] [0] DEBUG: Got ACK (0) of
79e9211b-14cb-4bf5-8a66-686cce9f005f
<----------------------------------------------------
2006-12-04 12:51:18 [31491] [0] DEBUG: HTTP: Resetting HTTPClient for
`127.0.0.1'.
2006-12-04 12:51:18 [31491] [1] DEBUG: HTTP: Destroying HTTPClient area
0x6446a0.
2006-12-04 12:51:18 [31491] [1] DEBUG: HTTP: Destroying HTTPClient for
`127.0.0.1'.
2006-12-04 12:51:18 [31491] [4] INFO: Starting delivery report <kannel_a> from
<3686>
2006-12-04 12:51:18 [31491] [9] DEBUG: Parsing URL
`http://localhost/ms/dlr.php?msgid=M061204125117_716_567&state=8&msisdn=83384401&A=ACK%2F&ts=2006-12-04+15:51:18&oper=2&smscid=SMPPpub&systype=MS_pub_3686':
2006-12-04 12:51:18 [31491] [9] DEBUG: Scheme: http://
2006-12-04 12:51:18 [31491] [9] DEBUG: Host: localhost
2006-12-04 12:51:18 [31491] [9] DEBUG: Port: 80
2006-12-04 12:51:18 [31491] [9] DEBUG: Username: (null)
2006-12-04 12:51:18 [31491] [9] DEBUG: Password: (null)
2006-12-04 12:51:18 [31491] [9] DEBUG: Path: /ms/dlr.php
2006-12-04 12:51:18 [31491] [9] DEBUG: Query:
msgid=M061204125117_716_567&state=8&msisdn=83384401&A=ACK%2F&ts=2006-12-04+15:51:18&oper=2&smscid=SMPPpub&sy
stype=MS_pub_3686
2006-12-04 12:51:18 [31491] [9] DEBUG: Fragment: (null)
2006-12-04 12:51:18 [31491] [9] DEBUG: HTTP: Opening connection to
`localhost:80' (fd=28).
2006-12-04 12:51:18 [31491] [9] DEBUG: Socket connecting
2006-12-04 12:51:18 [31491] [8] DEBUG: Get info about connecting socket
2006-12-04 12:51:18 [31491] [8] DEBUG: HTTP: Sending request:
2006-12-04 12:51:18 [31491] [8] DEBUG: Octet string at 0x654520:
2006-12-04 12:51:18 [31491] [8] DEBUG: len: 204
2006-12-04 12:51:18 [31491] [8] DEBUG: size: 1024
2006-12-04 12:51:18 [31491] [8] DEBUG: immutable: 0
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 47 45 54 20 2f 6d 73 2f 64 6c 72
2e 70 68 70 3f GET /ms/dlr.php?
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 6d 73 67 69 64 3d 4d 30 36 31 32
30 34 31 32 35 msgid=M061204125
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 31 31 37 5f 37 31 36 5f 35 36 37
26 73 74 61 74 117_716_567&stat
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 65 3d 38 26 6d 73 69 73 64 6e 3d
38 33 33 38 34 e=8&msisdn=83384
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 34 30 31 26 41 3d 41 43 4b 25 32
46 26 74 73 3d 401&A=ACK%2F&ts=
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 32 30 30 36 2d 31 32 2d 30 34 2b
31 35 3a 35 31 2006-12-04+15:51
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 3a 31 38 26 6f 70 65 72 3d 32 26
73 6d 73 63 69 :18&oper=2&smsci
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 64 3d 53 4d 50 50 70 75 62 26 73
79 73 74 79 70 d=SMPPpub&systyp
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 65 3d 4d 53 5f 70 75 62 5f 33 36
38 36 20 48 54 e=MS_pub_3686 HT
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 54 50 2f 31 2e 31 0d 0a 48 6f 73
74 3a 20 6c 6f TP/1.1..Host: lo
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 63 61 6c 68 6f 73 74 0d 0a 55 73
65 72 2d 41 67 calhost..User-Ag
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 65 6e 74 3a 20 4b 61 6e 6e 65 6c
2f 63 76 73 2d ent: Kannel/cvs-
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 32 30 30 36 31 30 31 32 0d 0a 0d
0a 20061012....
2006-12-04 12:51:18 [31491] [8] DEBUG: Octet string dump ends.
2006-12-04 12:51:18 [31491] [8] DEBUG: HTTP: Status line: <HTTP/1.1 200 OK>
2006-12-04 12:51:18 [31491] [8] DEBUG: HTTP: Received response:
2006-12-04 12:51:18 [31491] [8] DEBUG: Octet string at 0x647420:
2006-12-04 12:51:18 [31491] [8] DEBUG: len: 143
2006-12-04 12:51:18 [31491] [8] DEBUG: size: 1024
2006-12-04 12:51:18 [31491] [8] DEBUG: immutable: 0
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 44 61 74 65 3a 20 4d 6f 6e 2c 20
30 34 20 44 65 Date: Mon, 04 De
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 63 20 32 30 30 36 20 31 35 3a 35
31 3a 31 38 20 c 2006 15:51:18
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 47 4d 54 0d 0a 53 65 72 76 65 72
3a 20 41 70 61 GMT..Server: Apa
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 63 68 65 2f 32 2e 32 2e 30 20 28
4c 69 6e 75 78 che/2.2.0 (Linux
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 2f 53 55 53 45 29 0d 0a 58 2d 50
6f 77 65 72 65 /SUSE)..X-Powere
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 64 2d 42 79 3a 20 50 48 50 2f 35
2e 31 2e 32 0d d-By: PHP/5.1.2.
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 0a 43 6f 6e 74 65 6e 74 2d 4c 65
6e 67 74 68 3a .Content-Length:
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 20 30 0d 0a 43 6f 6e 74 65 6e 74
2d 54 79 70 65 0..Content-Type
2006-12-04 12:51:18 [31491] [8] DEBUG: data: 3a 20 74 65 78 74 2f 68 74 6d 6c
0d 0a 0d 0a : text/html....
2006-12-04 12:51:18 [31491] [8] DEBUG: Octet string dump ends.
On Thursday November 30 2006 07:13, Ben Suffolk wrote:
> Did you check the smsc logs as opposed to the core logs?
>
> It sounds a bit like the SMPP connection dropped out. This would not
> show in the main core logs, but in the smsc logs.
>
> Regards
>
> Ben
> On 30 Nov 2006, at 10:07, Fourat Zouari wrote:
>
> > did you reolve the problem ?
> > i've got the same issue than you.
> > I can't reproduce it.
> >
> >
> > On 11/8/06, Marcelo Aguila < [EMAIL PROTECTED]> wrote:
> > Hi.
> >
> > I'm recently started to work with an operator that use SMPP 3.4 so
> > I'm using
> > kannel 1.4.1 (CVS) in a Dell PowerEdge 2950 with one intel xeon
> > dual core
> > processor.
> >
> > Since the problem started I've not touched nor reinitializing
> > anything to see
> > what is happening.
> >
> > Well, after several days of testing suddenly my logs shows that since
> > 2006-11-02 16:55 to 2006-11-07 17:43 (for 5 days) the sendsms
> > started to
> > return "Queued for later delivery" (158 messages).
> >
> > So, without any intervention since 2006-11-07 17:53 until now (17 new
> > messages), sendsms started to return "Accepted for delivery"
> >
> > I could check that first queued message was delivered to SMSC at
> > 2006-11-03
> > 02:41 (almost 12 hours after its creation) and the delivery to the
> > phone was
> > made a minute later at 2:42.
> >
> > Why the messages could be queued for later delivey and why the
> > problem stopped
> > 5 days later without any manual intervention.
> >
> > I'm lost because I can't find any clue in the logs (they are
> > configured in
> > debug mode).
> > What could it be, a configuration problem, a communication problem
> > with
> > operator ?
> >
> > Please, any tip?
> >
> > M.
> >
> >
>
>
