You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by bu...@apache.org on 2006/08/23 10:00:49 UTC
DO NOT REPLY [Bug 40303] New: - Time order problem in multithreaded environment
DO NOT REPLY TO THIS EMAIL, BUT PLEASE POST YOUR BUG�
RELATED COMMENTS THROUGH THE WEB INTERFACE AVAILABLE AT
<http://issues.apache.org/bugzilla/show_bug.cgi?id=40303>.
ANY REPLY MADE TO THIS MESSAGE WILL NOT BE COLLECTED AND�
INSERTED IN THE BUG DATABASE.
http://issues.apache.org/bugzilla/show_bug.cgi?id=40303
Summary: Time order problem in multithreaded environment
Product: Log4j
Version: 1.2
Platform: PC
OS/Version: Linux
Status: NEW
Severity: normal
Priority: P2
Component: Appender
AssignedTo: log4j-dev@logging.apache.org
ReportedBy: thomas.reitz@wincor-nixdorf.com
Entries in the log file do not appear in correct date and time order in
multithreaded environment.
- configuration file log4j.properties
log4j.rootLogger=DEBUG, T
log4j.appender.T=org.apache.log4j.RollingFileAppender
log4j.appender.T.File=/home/proview/gateway/data/trace/PVGATEWAY.TRC
log4j.appender.T.MaxFileSize=10000KB
log4j.appender.T.MaxBackupIndex=3
log4j.appender.T.layout=org.apache.log4j.PatternLayout
log4j.appender.T.layout.ConversionPattern=%d %-5p [%-20t] %-80m [%l]%n
- parts of the log file PVGATEWAY.TRC
Even for one thread the entries do not appear in correct date and time order.
2006-08-23 09:41:35,715 DEBUG [ComMessageDispatcher] session: [Session-199, S
2006-08-23 09:41:33,597 DEBUG [ComMessageDispatcher] SerialNumber:
1155890229
2006-08-23 09:41:33,599 DEBUG [ComMessageDispatcher] SubjectDN:
CN=XXXXXXXXXXXXXXXXX, OU=psd8, O=wn,
2006-08-23 09:41:33,600 DEBUG [ComMessageDispatcher] TBSCertificate:
[B@e22f2b
2006-08-23 09:41:33,601 DEBUG [ComMessageDispatcher] PublicKey: SunJSSE RSA
public key:
2006-08-23 09:41:35,733 DEBUG [SsopServerSocket ] run: accepted new socket:
Socket[addr=/AAA.18.177.DDD,port=2665,localport=18988]
2006-08-23 09:41:35,733 DEBUG [SsopServerSocket ] accept: accept socketSocket
[addr=/AAA.18.177.DDD,port=2665,localport=18988]
2006-08-23 09:41:35,734 DEBUG [SsopServerSocket ] constructor: Socket =
Socket[addr=/AAA.18.177.DDD,port=2665,localport=18988]
2006-08-23 09:41:35,734 DEBUG [SsopServerSocket ] constructor:
com.YYYYYYYYYYYYY.proview.conmgr.ssop.PVAgentSsopSocket
2006-08-23 09:41:35,735 DEBUG [SsopServerSocket ] createSsopCient: enter
2006-08-23 09:41:35,746 DEBUG [SsopServerSocket ] open entered
socket:/AAA.18.177.DDD:2665
2006-08-23 09:41:35,747 DEBUG [ComMessageDispatcher] host name: XXXXX239
2006-08-23 09:41:35,748 DEBUG [ComMessageDispatcher] host ip address:
AAA.18.62.DD
2006-08-23 09:41:33,624 DEBUG [SsopServerSocket ] createSsopServer: enter
2006-08-23 09:41:33,625 DEBUG [SsopServerSocket ] constructor:
PVAgentSsopServer:AGMGR01EVT
2006-08-23 09:41:33,625 DEBUG [SsopServerSocket ]
constructor
2006-08-23 09:41:33,626 DEBUG [SsopServerSocket ] messageController=
com.YYYYYYYYYYYYY.proview.gateway.GatewaymessageConsumer
2006-08-23 09:41:33,626 DEBUG [SsopServerSocket ] addServiceProvider, maybe
invalid number: 304
2006-08-23 09:41:33,627 DEBUG [SsopServerSocket ] addServiceProvider, maybe
invalid number: 310
2006-08-23 09:41:33,627 DEBUG [SsopServerSocket ] addServiceProvider, maybe
invalid number: 301
2006-08-23 09:41:33,628 DEBUG [SsopServerSocket ] addServiceProvider, maybe
invalid number: 356
2006-08-23 09:41:35,749 DEBUG [ComMessageDispatcher] session: [Session-200,
SSL_RSA_WITH_RC4_128_MD5]
2006-08-23 09:41:33,624 DEBUG [SocketReader ] run
entered
2006-08-23 09:41:33,629 DEBUG [SsopServerSocket ] addServiceProvider, maybe
invalid number: 357
2006-08-23 09:41:35,757 DEBUG [ComMessageDispatcher] response to
https://XXXXX239:8443/ProviewEventService/EventServlet= OK
2006-08-23 09:41:35,760 DEBUG [ComMessageDispatcher] addDevice: terminalId =
ATMa_00198, hostname = AAA.18.177.DDD, port = 18988
2006-08-23 09:41:35,761 DEBUG [ComMessageDispatcher] accept: ATMa_00198
java.util.GregorianCalendar[time=?,areFieldsSet=fal
2006-08-23 09:41:35,757 DEBUG [SocketReader ] run: 107 bytes expected
from :/AAA.18.177.DDD:2665
2006-08-23 09:41:35,762 DEBUG [ComMessageDispatcher] write
entered:/AAA.18.177.DDD:2659
2006-08-23 09:41:35,765 DEBUG [ComMessageDispatcher] IssuerDN:
CN=XXXXXXXXXXXXXXXXX, OU=psd8, O=wn, L=frankfurt, ST=hessen, C=he
2006-08-23 09:41:33,641 INFO [ComMessageDispatcher] >>> ATMa_00198
UR002010701AGMGR01 00002003
2006-08-23 09:41:35,770 DEBUG [ComMessageDispatcher] TBSCertificate:
[B@17cf6b6
2006-08-23 09:41:33,647 DEBUG [ComMessageDispatcher] messageReceived:
com.YYYYYYYYYYYYY.proview.ssop.PvSsopMsgEnvelop@1295fe8
--
Configure bugmail: http://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
DO NOT REPLY [Bug 40303] - Time order problem in multithreaded environment
Posted by bu...@apache.org.
DO NOT REPLY TO THIS EMAIL, BUT PLEASE POST YOUR BUG�
RELATED COMMENTS THROUGH THE WEB INTERFACE AVAILABLE AT
<http://issues.apache.org/bugzilla/show_bug.cgi?id=40303>.
ANY REPLY MADE TO THIS MESSAGE WILL NOT BE COLLECTED AND�
INSERTED IN THE BUG DATABASE.
http://issues.apache.org/bugzilla/show_bug.cgi?id=40303
carnold@apache.org changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEW |RESOLVED
Resolution| |WONTFIX
------- Additional Comments From carnold@apache.org 2006-08-29 23:31 -------
This is a known cosmetic defect in log4j, though I could not find a previously logged bug in a search.
Previously discussed in a thread on log4j-user in late August, early Sept 2005, see http://
marc.theaimsgroup.com/?l=log4j-user&m=112567762307503&w=2.
Basically, getting timestamp occurs in one synchronization block and output to the appender in
another. There is no guarantee that the thread that got the first timestamp will be the first to be
released if the thread blocks in the later block. If the issue is significant for you, then I would
recommend using the "new" AsyncAppender (in the SVN but not in 1.2.13 or 1.3 alpha 9) with
blocking=false. This should minimize the potential for threads to block in a manner that would
misorder the timestamps.
After much research and discussion, I'm convinced that there is no simple solution to the problem that
would not potentially add significant compatibility issues. Maybe in log4j 2.0, this could be addressed.
But not in log4j 1.2 or 1.3.
--
Configure bugmail: http://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org