Howto Read playSMS Log
This is a draft post.
This is a sample of log when user send an SMS, from user hits the send SMS button up to the SMS flagged delivered.
Full log
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L2 sendsms # start uid:1 sender_id:[1234] smsc:[]
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L3 sendsms # maxlen:459 footerlen:7 footer:[ @admin] msglen:6 message:[Test 1]
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L2 sendsms_queue_create # saving queue_code:21c462193314dd03ec3f031ba4a481c9 src:1234 scheduled:2020-11-11 16:09:06
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L2 sendsms_queue_create # saved queue_code:21c462193314dd03ec3f031ba4a481c9 id:1
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L3 sendsms_manipulate_prefix # before prefix manipulation:[1234]
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L3 sendsms_manipulate_prefix # after prefix manipulation:[1234]
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L3 simplerate_hook_rate_getbyprefix # rate not found to:1234 default_rate:0
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L3 simplerate_hook_rate_getcharges # uid:1 u:admin len:13 unicode:0 to:1234 enable_credit_unicode:0 count:1 rate: charge:0
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L2 sendsms # dst_count:1 sms_count:1 total_charges:0
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L2 sendsms_queue_push # saving queue_code:21c462193314dd03ec3f031ba4a481c9 dst:1234
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L2 sendsms_queue_push # saved queue_code:21c462193314dd03ec3f031ba4a481c9 smslog_id:1
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L2 sendsms # end queue_code:21c462193314dd03ec3f031ba4a481c9 queue_count:1 sms_count:1 failed_queue:0 failed_sms:0
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 sendsmsd # start processing queue_code:21c462193314dd03ec3f031ba4a481c9 chunk:0 queue_count:1 sms_count:1 scheduled:2020-11-11 16:09:06 uid:1 gpid:0 sender_id:1234
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 sendsmsd # sending queue_code:21c462193314dd03ec3f031ba4a481c9 smslog_id:1 to:1234 sms_count:1 counter:1
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L3 sendsms_intercept # msgtemplate modified sms_sender:[1234] sms_footer:[@admin] sms_to:[1234] sms_msg:[Test 1] uid:[1] gpid:[0] sms_type:[text] unicode:[0] queue_code:[21c462193314dd03ec3f031ba4a481c9] smsc:[]
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L3 outgoing_hook_sendsms_intercept # no SMSC found uid:1 parent_uid:0 from:1234 to:1234
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 recvsms_process # using default SMSC smsc:[dev]
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 sendsms_process # start
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L3 simplerate_hook_rate_getbyprefix # rate not found to:1234 default_rate:0
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L3 simplerate_hook_rate_getcharges # uid:1 u:admin len:13 unicode:0 to:1234 enable_credit_unicode:0 count:1 rate: charge:0
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 simplerate_hook_rate_cansend # allowed user uid:1 sms_to:1234 adhoc_credit:0 count:1 rate: charge:0 adhoc_balance:0
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 sendsms # saving smslog_id:1 u:1 parent_uid:0 g:0 gw:dev smsc:dev s:1234 d:1234 type:text unicode:0 status:0
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 sendsms_process # saved smslog_id:1 id:1
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L3 sendsms # final smslog_id:1 gw:dev smsc:dev message:Test 1 @admin len:13
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L3 dev_hook_sendsms # enter smsc:dev smslog_id:1 uid:1 to:1234
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L3 dlr # isdlrd:1 smslog_id:1 p_status:3 uid:1
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 simplerate_hook_rate_deduct # enter smslog_id:1
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L3 simplerate_hook_rate_getbyprefix # rate not found to:1234 default_rate:0
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L3 simplerate_hook_rate_getcharges # uid:1 u:admin len:13 unicode:0 to:1234 enable_credit_unicode:0 count:1 rate: charge:0
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 simplebilling_hook_billing_post # saving smslog_id:1 rate:0 count:1 charge:0
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 simplebilling_hook_billing_post # saved smslog_id:1 id:1
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L3 simplerate_hook_rate_deduct # deduct successful uid:1 parent_uid:0 smslog_id:1
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 sendsms_process # end
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 sendsmsd # result queue_code:21c462193314dd03ec3f031ba4a481c9 to:1234 flag:1 smslog_id:1
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 sendsmsd # finish processing queue_code:21c462193314dd03ec3f031ba4a481c9 uid:1 sender_id:1234 queue_count:1 sms_count:1
- - 2020-11-11 16:09:09 PID5fac0a59d1353 - L3 dlrd # id:1 smslog_id:1 p_status:3 uid:1
- - 2020-11-11 16:09:09 PID5fac0a59d1353 - L2 simplebilling__finalize # saving smslog_id:1
- - 2020-11-11 16:09:09 PID5fac0a59d1353 - L2 simplebilling__finalize # saved smslog_id:1
Above long log entries can be devided into 3 parts. We can devide them by log tags started with PID. Those tags are unique per process, lets just say they are process IDs, hence the tag prefix PID.
Let’s break it down
1st part
Tagged with process ID PID5fac0ca250eba.
1st part of the log is log entries when user submit an SMS from playSMS send SMS menu or webservices, or other methods invoking sendsms() or sendsms_helper() function.
In this part we can read if playSMS sucessfully process submitted SMS to a queue or not. Note that we can see the server IP (192.168.56.1) and originating/remote/user IP address (192.168.56.111).
This part of the log started with sendsms # start and finished with sendsms # end.
1st part:
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L2 sendsms # start uid:1 sender_id:[1234] smsc:[]
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L3 sendsms # maxlen:459 footerlen:7 footer:[ @admin] msglen:6 message:[Test 1]
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L2 sendsms_queue_create # saving queue_code:21c462193314dd03ec3f031ba4a481c9 src:1234 scheduled:2020-11-11 16:09:06
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L2 sendsms_queue_create # saved queue_code:21c462193314dd03ec3f031ba4a481c9 id:1
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L3 sendsms_manipulate_prefix # before prefix manipulation:[1234]
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L3 sendsms_manipulate_prefix # after prefix manipulation:[1234]
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L3 simplerate_hook_rate_getbyprefix # rate not found to:1234 default_rate:0
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L3 simplerate_hook_rate_getcharges # uid:1 u:admin len:13 unicode:0 to:1234 enable_credit_unicode:0 count:1 rate: charge:0
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L2 sendsms # dst_count:1 sms_count:1 total_charges:0
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L2 sendsms_queue_push # saving queue_code:21c462193314dd03ec3f031ba4a481c9 dst:1234
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L2 sendsms_queue_push # saved queue_code:21c462193314dd03ec3f031ba4a481c9 smslog_id:1
192.168.56.1 192.168.56.111 2020-11-11 16:09:06 PID5fac0ca250eba admin L2 sendsms # end queue_code:21c462193314dd03ec3f031ba4a481c9 queue_count:1 sms_count:1 failed_queue:0 failed_sms:0
2nd part
Tagged with process ID PID5fac0ca42cc68.
2nd part of the log is log entries made by sendsmsd, playSMS daemon script called sendsmsd. This daemon reads queues periodically, process them and process all SMS inside the queue for delivery to the selected SMSC. Note that in 2nd part we cannot see any IP address because this part written by daemon scripts.
This part of the log started with sendsmsd # start processing and finished with sendsmsd # finish processing.
2nd part:
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 sendsmsd # start processing queue_code:21c462193314dd03ec3f031ba4a481c9 chunk:0 queue_count:1 sms_count:1 scheduled:2020-11-11 16:09:06 uid:1 gpid:0 sender_id:1234
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 sendsmsd # sending queue_code:21c462193314dd03ec3f031ba4a481c9 smslog_id:1 to:1234 sms_count:1 counter:1
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L3 sendsms_intercept # msgtemplate modified sms_sender:[1234] sms_footer:[@admin] sms_to:[1234] sms_msg:[Test 1] uid:[1] gpid:[0] sms_type:[text] unicode:[0] queue_code:[21c462193314dd03ec3f031ba4a481c9] smsc:[]
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L3 outgoing_hook_sendsms_intercept # no SMSC found uid:1 parent_uid:0 from:1234 to:1234
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 recvsms_process # using default SMSC smsc:[dev]
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 sendsms_process # start
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L3 simplerate_hook_rate_getbyprefix # rate not found to:1234 default_rate:0
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L3 simplerate_hook_rate_getcharges # uid:1 u:admin len:13 unicode:0 to:1234 enable_credit_unicode:0 count:1 rate: charge:0
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 simplerate_hook_rate_cansend # allowed user uid:1 sms_to:1234 adhoc_credit:0 count:1 rate: charge:0 adhoc_balance:0
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 sendsms # saving smslog_id:1 u:1 parent_uid:0 g:0 gw:dev smsc:dev s:1234 d:1234 type:text unicode:0 status:0
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 sendsms_process # saved smslog_id:1 id:1
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L3 sendsms # final smslog_id:1 gw:dev smsc:dev message:Test 1 @admin len:13
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L3 dev_hook_sendsms # enter smsc:dev smslog_id:1 uid:1 to:1234
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L3 dlr # isdlrd:1 smslog_id:1 p_status:3 uid:1
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 simplerate_hook_rate_deduct # enter smslog_id:1
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L3 simplerate_hook_rate_getbyprefix # rate not found to:1234 default_rate:0
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L3 simplerate_hook_rate_getcharges # uid:1 u:admin len:13 unicode:0 to:1234 enable_credit_unicode:0 count:1 rate: charge:0
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 simplebilling_hook_billing_post # saving smslog_id:1 rate:0 count:1 charge:0
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 simplebilling_hook_billing_post # saved smslog_id:1 id:1
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L3 simplerate_hook_rate_deduct # deduct successful uid:1 parent_uid:0 smslog_id:1
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 sendsms_process # end
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 sendsmsd # result queue_code:21c462193314dd03ec3f031ba4a481c9 to:1234 flag:1 smslog_id:1
- - 2020-11-11 16:09:08 PID5fac0ca42cc68 - L2 sendsmsd # finish processing queue_code:21c462193314dd03ec3f031ba4a481c9 uid:1 sender_id:1234 queue_count:1 sms_count:1
3rd part
Tagged with process ID PID5fac0a59d1353.
3rd part of the log is log entries made by dlrd, playSMS daemon script called dlrssmsd. This daemon reads delivery reports from SMSC.
3rd part:
- - 2020-11-11 16:09:09 PID5fac0a59d1353 - L3 dlrd # id:1 smslog_id:1 p_status:3 uid:1
- - 2020-11-11 16:09:09 PID5fac0a59d1353 - L2 simplebilling__finalize # saving smslog_id:1
- - 2020-11-11 16:09:09 PID5fac0a59d1353 - L2 simplebilling__finalize # saved smslog_id:1
Summary
Notes:
- A full SMS process will be written in 3 parts
- 1st part is written when user send SMS and playSMS save it in a queue for delivery
- 2nd part is written when playSMS daemon script reads queues, process them and deliver SMS to selected SMSC for actual delivery
- 3rd part is written also by playSMS daemon script when delivery reports received
Tips for debugging:
- Each SMS submission will have unique process ID
- Each SMS will have smslog_id, you can debug the delivery by searching for it
- When you saw only 1st part that could mean error happened on SMS submission or the daemon script is not running properly hence no 2nd part and 3rd
To be continue.