[Devel] [ openser-Bugs-1681290 ] Timestamp accounting broken when $sp is logged

[SourceForge.net]

Bugs item #1681290, was opened at 2007-03-15 11:56
Message generated for change (Comment added) made by bogdan_iancu
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=743020&aid=1681290&group_id=139143

Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
>Category: core
Group: ver 1.2.x
>Status: Closed
>Resolution: Fixed
Priority: 5
Private: No
Submitted By: axlh (axlh)
>Assigned to: Bogdan (bogdan_iancu)
Summary: Timestamp accounting broken when $sp is logged

Initial Comment:
Hi,

when i try to log BOTH the timestamp and the source port for accounting, the last digits of the timestamp get overwritten by the port number. See below for example.



Broken behaviour:
modparam("acc", "log_extra", "time_stamp=$Ts; src_port=$sp")

Mar 15 10:46:15 proxy1 proxy1[8706]: ACC: transaction answered: timestamp=1173951975;method=INVITE;from_tag=azqam;to_tag=as4b3acde6;call_id=yhfuamdhubshdku at 172.28.4.186;code=200;reason=OK;time_stamp=1173955060;src_port=5060


Without $sp, this works fine (although timestamp and time_stamp are different, why?):
modparam("acc", "log_extra", "time_stamp=$Ts")

Mar 15 10:52:05 proxy1 proxy1[9102]: ACC: call missed: timestamp=1173952325;method=INVITE;from_tag=efizq;to_tag=;call_id=cyzpmzjfmazyfsa at 172.28.4.186;code=487;reason=Request Terminated;time_stamp=1173952323



version: openser 1.2.0-pre8-tls (i386/linux)
flags: STATS: Off, USE_IPV6, USE_TCP, USE_TLS, DISABLE_NAGLE, USE_MCAST, SHM_MEM, SHM_MMAP, PKG_MALLOC, F_MALLOC, FAST_LOCK-ADAPTIVE_WAIT
ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535
poll method support: poll, epoll_lt, epoll_et, sigio_rt, select.
svnrevision: 2:1821M
@(#) $Id: main.c 1746 2007-03-05 16:06:58Z miconda $
main.c compiled on 09:33:14 Mar 12 2007 with gcc 4.1.2


----------------------------------------------------------------------

>Comment By: Bogdan (bogdan_iancu)
Date: 2007-03-15 14:32

Message:
Logged In: YES 
user_id=1275325
Originator: NO

Thanks for report,

the issue was fixed on both 1.2 and devel branches

----------------------------------------------------------------------

Comment By: axlh (axlh)
Date: 2007-03-15 12:20

Message:
Logged In: YES 
user_id=1212856
Originator: YES

And another case. Seems $sp and $Ts are sharing a buffer in accounting. 

modparam("acc", "log_extra", "stamp1=$Ts; src_port=$sp; stamp2=$Ts")

Mar 15 11:04:38 proxy1 proxy1[9758]: ACC: transaction answered:
timestamp=1173953078;method=CANCEL;from_tag=bhfjy;to_tag=;call_id=xccwquxpnkjplyp at 172.28.4.186;code=200;reason=OK;stamp1=1173953078;src_port=3078;stamp2=1173953078

(Actual source port is 5060)



This doesn't happen during the normal route processing, only on
accounting. The following snippet:

xlog("Current timestamp: $Ts");
xlog("Current timestamp: $Ts   Port: $sp");
xlog("Current timestamp: $Ts   Port: $sp");

produces this log:
Mar 15 11:04:38 proxy1 proxy1[9758]: Current timestamp: 1173953078
Mar 15 11:04:38 proxy1 proxy1[9758]: Current timestamp: 1173953078   Port:
5060
Mar 15 11:04:38 proxy1 proxy1[9758]: Current timestamp: 1173953078   Port:
5060

Nothing seems wrong here.

----------------------------------------------------------------------

You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=743020&aid=1681290&group_id=139143