2012-04-24 14:23:38,758:INFO :[http-0.0.0.0-8080-23]:[com.arrow.bsc.BillingConnectorManager]:BSC:RELOAD:START:TID=26746;MSISDN=3515956188:AMOUNT=10.0 2012-04-24 14:23:38,759:INFO :[http-0.0.0.0-8080-23]:[com.arrow.bsc.BillingConnectorRouter]:BSC_ROUTER:ROUTE:START:MSISDN=3515956188 2012-04-24 14:23:38,773:INFO :[http-0.0.0.0-8080-23]:[com.arrow.bsc.BillingConnectorRouter]:BSC_ROUTER:ROUTE:END:MSISDN=3515956188;PATH=BILLING-AR-4:0.015:OK 2012-04-24 14:23:38,773:INFO :[http-0.0.0.0-8080-23]:[com.arrow.bsc.billing.connector.BillingConnector]:BSC_BILLING:RELOAD:START:TID=26746;MSISDN=3515956188:AMOUNT=10.0 2012-04-24 14:23:38,773:INFO :[http-0.0.0.0-8080-23]:[com.arrow.bsc.billing.connector.BillingReloadCommand]:BSC_BILLING:RELOAD:LOG:TID=26746;MSISDN=3515956188:AMOUNT=10.0 2012-04-24 14:23:38,773:INFO :[http-0.0.0.0-8080-23]:[com.arrow.bsc.billing.connector.specification.fundaccounttransfer.r47.FundAccountTransferReloadSpecificationCommand]:Starting the FundAccountTransferReloadSpecificationCommand execution (MSISDN = 3515956188, correlationId = 26746, amount = 10,00)... 2012-04-24 14:23:38,773:INFO :[http-0.0.0.0-8080-23]:[com.arrow.bsc.billing.connector.specification.fundaccounttransfer.r47.FundAccountTransferReloadSpecificationCommand]:Starting the fundAccountTransfer execution (MSISDN = 3515956188)... 2012-04-24 14:23:38,773:INFO :[http-0.0.0.0-8080-23]:[com.arrow.bsc.billing.connector.specification.fundaccounttransfer.r47.FundAccountTransferReloadSpecificationCommand]:Normalized MSISDN = 5493515956188 2012-04-24 14:23:38,775:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaClientRequestDispatcherImpl(http-0.0.0.0-8080-23): .beginRequest->: op/fundAccountTransfer 2012-04-24 14:23:38,778:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaOutboundConnectionCacheImpl(http-0.0.0.0-8080-23): .get: SocketOrChannelContactInfoImpl[IIOP_CLEAR_TEXT 10.48.27.142 1603] -946513569 2012-04-24 14:23:38,779:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaOutboundConnectionCacheImpl(http-0.0.0.0-8080-23): .stats: 1/total 0/busy 1/idle (240/100/5) 2012-04-24 14:23:38,779:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaClientRequestDispatcherImpl(http-0.0.0.0-8080-23): .beginRequest: op/fundAccountTransfer: Using cached connection: SocketOrChannelConnectionImpl[ Socket[addr=ctp-2-region3/10.48.27.142,port=1603,localport=40586] ESTABLISHED false true false] 2012-04-24 14:23:38,780:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaClientRequestDispatcherImpl(http-0.0.0.0-8080-23): .beginRequest: op/fundAccountTransfer id/179: created message mediator: com.sun.corba.se.impl.protocol.CorbaMessageMediatorImpl@3f00cf 2012-04-24 14:23:38,781:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaClientRequestDispatcherImpl(http-0.0.0.0-8080-23): .beginRequest: op/fundAccountTransfer id/179: created output object: com.sun.corba.se.impl.encoding.CDROutputObject@188e30b 2012-04-24 14:23:38,784:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaResponseWaitingRoomImpl(http-0.0.0.0-8080-23): .registerWaiter: op/fundAccountTransfer id/179 2012-04-24 14:23:38,784:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaOutboundConnectionCacheImpl(http-0.0.0.0-8080-23): .reclaim->: 1 (240/100/5) 2012-04-24 14:23:38,785:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaOutboundConnectionCacheImpl(http-0.0.0.0-8080-23): .reclaim<-: 1 2012-04-24 14:23:38,785:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaClientRequestDispatcherImpl(http-0.0.0.0-8080-23): .beginRequest: op/fundAccountTransfer id/179: initialized message 2012-04-24 14:23:38,785:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaClientRequestDispatcherImpl(http-0.0.0.0-8080-23): .beginRequest<-: op/fundAccountTransfer 2012-04-24 14:23:38,786:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaClientRequestDispatcherImpl(http-0.0.0.0-8080-23): .marshalingComplete->: op/fundAccountTransfer id/179 2012-04-24 14:23:38,788:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CDROutputObject(http-0.0.0.0-8080-23): .writeTo: SocketOrChannelConnectionImpl[ Socket[addr=ctp-2-region3/10.48.27.142,port=1603,localport=40586] ESTABLISHED false true false] 2012-04-24 14:23:38,788:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaClientRequestDispatcherImpl(http-0.0.0.0-8080-23): .marshalingComplete: op/fundAccountTransfer id/179: finished sending request 2012-04-24 14:23:38,788:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaResponseWaitingRoomImpl(http-0.0.0.0-8080-23): .waitForResponse->: op/fundAccountTransfer id/179 2012-04-24 14:23:38,789:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaResponseWaitingRoomImpl(http-0.0.0.0-8080-23): .waitForResponse: waiting: op/fundAccountTransfer id/179 2012-04-24 14:23:39,236:INFO :[p: default-threadpool; w: 3401]:[STDOUT]:SocketOrChannelConnectionImpl(p: default-threadpool; w: 3401): .readBits: SocketOrChannelConnectionImpl[ Socket[addr=ctp-2-region3/10.48.27.142,port=1603,localport=40586] ESTABLISHED false true false]: Throwable: org.omg.CORBA.COMM_FAILURE: vmcid: SUN minor code: 211 completed: No 2012-04-24 14:23:39,237:INFO :[p: default-threadpool; w: 3401]:[STDOUT]:org.omg.CORBA.COMM_FAILURE: vmcid: SUN minor code: 211 completed: No 2012-04-24 14:23:39,237:INFO :[p: default-threadpool; w: 3401]:[STDOUT]: at com.sun.corba.se.impl.logging.ORBUtilSystemException.ioexceptionWhenReadingConnection(ORBUtilSystemException.java:2456) 2012-04-24 14:23:39,237:INFO :[p: default-threadpool; w: 3401]:[STDOUT]: at com.sun.corba.se.impl.logging.ORBUtilSystemException.ioexceptionWhenReadingConnection(ORBUtilSystemException.java:2474) 2012-04-24 14:23:39,240:INFO :[p: default-threadpool; w: 3401]:[STDOUT]: at com.sun.corba.se.impl.protocol.giopmsgheaders.MessageBase.readGIOPHeader(MessageBase.java:116) 2012-04-24 14:23:39,240:INFO :[p: default-threadpool; w: 3401]:[STDOUT]: at com.sun.corba.se.impl.protocol.giopmsgheaders.MessageBase.readGIOPMessage(MessageBase.java:98) 2012-04-24 14:23:39,240:INFO :[p: default-threadpool; w: 3401]:[STDOUT]: at com.sun.corba.se.impl.transport.CorbaContactInfoBase.createMessageMediator(CorbaContactInfoBase.java:153) 2012-04-24 14:23:39,241:INFO :[p: default-threadpool; w: 3401]:[STDOUT]: at com.sun.corba.se.impl.transport.SocketOrChannelConnectionImpl.readBits(SocketOrChannelConnectionImpl.java:314) 2012-04-24 14:23:39,242:INFO :[p: default-threadpool; w: 3401]:[STDOUT]: at com.sun.corba.se.impl.transport.SocketOrChannelConnectionImpl.read(SocketOrChannelConnectionImpl.java:289) 2012-04-24 14:23:39,251:INFO :[p: default-threadpool; w: 3401]:[STDOUT]: at com.sun.corba.se.impl.transport.ReaderThreadImpl.doWork(ReaderThreadImpl.java:80) 2012-04-24 14:23:39,251:INFO :[p: default-threadpool; w: 3401]:[STDOUT]: at com.sun.corba.se.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(ThreadPoolImpl.java:398) 2012-04-24 14:23:39,251:INFO :[p: default-threadpool; w: 3401]:[STDOUT]:Caused by: java.net.SocketTimeoutException: Read timed out 2012-04-24 14:23:39,252:INFO :[p: default-threadpool; w: 3401]:[STDOUT]: at java.net.SocketInputStream.socketRead0(Native Method) 2012-04-24 14:23:39,253:INFO :[p: default-threadpool; w: 3401]:[STDOUT]: at java.net.SocketInputStream.read(SocketInputStream.java:129) 2012-04-24 14:23:39,253:INFO :[p: default-threadpool; w: 3401]:[STDOUT]: at java.io.FilterInputStream.read(FilterInputStream.java:116) 2012-04-24 14:23:39,254:INFO :[p: default-threadpool; w: 3401]:[STDOUT]: at com.wily.introscope.agent.probe.net.ManagedSocketInputStream.read(ManagedSocketInputStream.java:214) 2012-04-24 14:23:39,254:INFO :[p: default-threadpool; w: 3401]:[STDOUT]: at com.sun.corba.se.impl.transport.SocketOrChannelConnectionImpl.readFully(SocketOrChannelConnectionImpl.java:664) 2012-04-24 14:23:39,255:INFO :[p: default-threadpool; w: 3401]:[STDOUT]: at com.sun.corba.se.impl.transport.SocketOrChannelConnectionImpl.read(SocketOrChannelConnectionImpl.java:527) 2012-04-24 14:23:39,255:INFO :[p: default-threadpool; w: 3401]:[STDOUT]: at com.sun.corba.se.impl.protocol.giopmsgheaders.MessageBase.readGIOPHeader(MessageBase.java:112) 2012-04-24 14:23:39,255:INFO :[p: default-threadpool; w: 3401]:[STDOUT]: ... 6 more 2012-04-24 14:23:39,260:INFO :[p: default-threadpool; w: 3401]:[STDOUT]:SelectorImpl(p: default-threadpool; w: 3401): .unregisterForEvent: SocketOrChannelConnectionImpl[ Socket[addr=ctp-2-region3/10.48.27.142,port=1603,localport=40586] ESTABLISHED false true false] 2012-04-24 14:23:39,261:INFO :[p: default-threadpool; w: 3401]:[STDOUT]:SelectorImpl(p: default-threadpool; w: 3401): .destroyReaderThread: SocketOrChannelConnectionImpl[ Socket[addr=ctp-2-region3/10.48.27.142,port=1603,localport=40586] ESTABLISHED false true false] 2012-04-24 14:23:39,262:INFO :[p: default-threadpool; w: 3401]:[STDOUT]:ReaderThreadImpl(p: default-threadpool; w: 3401): .close: SocketOrChannelConnectionImpl[ Socket[addr=ctp-2-region3/10.48.27.142,port=1603,localport=40586] ESTABLISHED false true false] 2012-04-24 14:23:39,264:INFO :[p: default-threadpool; w: 3401]:[STDOUT]:SocketOrChannelConnectionImpl(p: default-threadpool; w: 3401): .purgeCalls->: 1398079696/true/false SocketOrChannelConnectionImpl[ Socket[addr=ctp-2-region3/10.48.27.142,port=1603,localport=40586] ESTABLISHED false true false] 2012-04-24 14:23:39,272:INFO :[p: default-threadpool; w: 3401]:[STDOUT]:SocketOrChannelConnectionImpl(p: default-threadpool; w: 3401): .purgeCalls: Exception closing socket: java.net.SocketException: Socket is closed SocketOrChannelConnectionImpl[ Socket[addr=ctp-2-region3/10.48.27.142,port=1603,localport=40586] ABORT false true false] 2012-04-24 14:23:39,273:INFO :[p: default-threadpool; w: 3401]:[STDOUT]:CorbaResponseWaitingRoomImpl(p: default-threadpool; w: 3401): .signalExceptionToAllWaiters: org.omg.CORBA.COMM_FAILURE: vmcid: SUN minor code: 208 completed: Maybe 2012-04-24 14:23:39,273:INFO :[p: default-threadpool; w: 3401]:[STDOUT]:CorbaOutboundConnectionCacheImpl(p: default-threadpool; w: 3401): .remove: SocketOrChannelContactInfoImpl[IIOP_CLEAR_TEXT 10.48.27.142 1603] -946513569 2012-04-24 14:23:39,274:INFO :[p: default-threadpool; w: 3401]:[STDOUT]:CorbaOutboundConnectionCacheImpl(p: default-threadpool; w: 3401): .stats: 0/total 0/busy 0/idle (240/100/5) 2012-04-24 14:23:39,279:INFO :[p: default-threadpool; w: 3401]:[STDOUT]:SocketOrChannelConnectionImpl(p: default-threadpool; w: 3401): .purgeCalls<-: 1398079696/true/false SocketOrChannelConnectionImpl[ Socket[addr=ctp-2-region3/10.48.27.142,port=1603,localport=40586] ABORT false true false] 2012-04-24 14:23:39,279:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaResponseWaitingRoomImpl(http-0.0.0.0-8080-23): .waitForResponse: exception: op/fundAccountTransfer id/179 2012-04-24 14:23:39,282:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaResponseWaitingRoomImpl(http-0.0.0.0-8080-23): .waitForResponse<-: op/fundAccountTransfer id/179 2012-04-24 14:23:39,286:INFO :[p: default-threadpool; w: 3401]:[STDOUT]:SocketOrChannelConnectionImpl(p: default-threadpool; w: 3401): .readBits<-: SocketOrChannelConnectionImpl[ Socket[addr=ctp-2-region3/10.48.27.142,port=1603,localport=40586] ABORT false true false] 2012-04-24 14:23:39,292:INFO :[p: default-threadpool; w: 3401]:[STDOUT]:SocketOrChannelConnectionImpl(p: default-threadpool; w: 3401): .read<-: SocketOrChannelConnectionImpl[ Socket[addr=ctp-2-region3/10.48.27.142,port=1603,localport=40586] ABORT false true false] 2012-04-24 14:23:39,293:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaClientRequestDispatcherImpl(http-0.0.0.0-8080-23): .marshalingComplete: op/fundAccountTransfer id/179: exception: org.omg.CORBA.COMM_FAILURE: vmcid: SUN minor code: 208 completed: Maybe 2012-04-24 14:23:39,299:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaClientRequestDispatcherImpl(http-0.0.0.0-8080-23): .marshalingComplete<-: op/fundAccountTransfer id/179 2012-04-24 14:23:39,300:INFO :[p: default-threadpool; w: 3401]:[STDOUT]:ReaderThreadImpl(p: default-threadpool; w: 3401): .doWork: Terminated ReaderThread: SocketOrChannelConnectionImpl[ Socket[addr=ctp-2-region3/10.48.27.142,port=1603,localport=40586] ABORT false true false] 2012-04-24 14:23:39,304:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaClientRequestDispatcherImpl(http-0.0.0.0-8080-23): .endRequest-> 2012-04-24 14:23:39,309:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:(ORB).impl.encoding.CDROutputStream_1_0(http-0.0.0.0-8080-23): .close - releasing ByteBuffer id (25974574) to ByteBufferPool. 2012-04-24 14:23:39,311:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaResponseWaitingRoomImpl(http-0.0.0.0-8080-23): .unregisterWaiter: op/fundAccountTransfer id/179 2012-04-24 14:23:39,311:INFO :[http-0.0.0.0-8080-23]:[STDOUT]:CorbaClientRequestDispatcherImpl(http-0.0.0.0-8080-23): .endRequest<- 2012-04-24 14:23:39,316:ERROR:[http-0.0.0.0-8080-23]:[com.arrow.bsc.billing.connector.specification.fundaccounttransfer.r47.FundAccountTransferReloadSpecificationCommand]:Error during fundAccountTransfer execution. org.omg.CORBA.COMM_FAILURE: vmcid: SUN minor code: 208 completed: Maybe at com.sun.corba.se.impl.logging.ORBUtilSystemException.connectionAbort(ORBUtilSystemException.java:2372) at com.sun.corba.se.impl.logging.ORBUtilSystemException.connectionAbort(ORBUtilSystemException.java:2390) at com.sun.corba.se.impl.transport.SocketOrChannelConnectionImpl.readBits(SocketOrChannelConnectionImpl.java:354) at com.sun.corba.se.impl.transport.SocketOrChannelConnectionImpl.read(SocketOrChannelConnectionImpl.java:289) at com.sun.corba.se.impl.transport.ReaderThreadImpl.doWork(ReaderThreadImpl.java:80) at com.sun.corba.se.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(ThreadPoolImpl.java:398) Caused by: org.omg.CORBA.COMM_FAILURE: vmcid: SUN minor code: 211 completed: No at com.sun.corba.se.impl.logging.ORBUtilSystemException.ioexceptionWhenReadingConnection(ORBUtilSystemException.java:2456) at com.sun.corba.se.impl.logging.ORBUtilSystemException.ioexceptionWhenReadingConnection(ORBUtilSystemException.java:2474) at com.sun.corba.se.impl.protocol.giopmsgheaders.MessageBase.readGIOPHeader(MessageBase.java:116) at com.sun.corba.se.impl.protocol.giopmsgheaders.MessageBase.readGIOPMessage(MessageBase.java:98) at com.sun.corba.se.impl.transport.CorbaContactInfoBase.createMessageMediator(CorbaContactInfoBase.java:153) at com.sun.corba.se.impl.transport.SocketOrChannelConnectionImpl.readBits(SocketOrChannelConnectionImpl.java:314) ... 3 more Caused by: java.net.SocketTimeoutException: Read timed out at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at java.io.FilterInputStream.read(FilterInputStream.java:116) at com.wily.introscope.agent.probe.net.ManagedSocketInputStream.read(ManagedSocketInputStream.java:214) at com.sun.corba.se.impl.transport.SocketOrChannelConnectionImpl.readFully(SocketOrChannelConnectionImpl.java:664) at com.sun.corba.se.impl.transport.SocketOrChannelConnectionImpl.read(SocketOrChannelConnectionImpl.java:527) at com.sun.corba.se.impl.protocol.giopmsgheaders.MessageBase.readGIOPHeader(MessageBase.java:112) ... 6 more 2012-04-24 14:23:39,319:ERROR:[http-0.0.0.0-8080-23]:[com.arrow.bsc.billing.connector.specification.fundaccounttransfer.r47.FundAccountTransferReloadSpecificationCommand]:TIMEOUT OCCURS DURING THE CONNECTION 2012-04-24 14:23:39,319:INFO :[http-0.0.0.0-8080-23]:[com.arrow.bsc.billing.connector.specification.fundaccounttransfer.r47.FundAccountTransferReloadSpecificationCommand]:Billing Result Code [100] 2012-04-24 14:23:39,319:INFO :[http-0.0.0.0-8080-23]:[com.arrow.bsc.billing.connector.specification.fundaccounttransfer.r47.FundAccountTransferReloadSpecificationCommand]:Finishing the fundAccountTransfer execution (MSISDN = 3515956188, billingReturnCode = 100). 2012-04-24 14:23:39,319:INFO :[http-0.0.0.0-8080-23]:[com.arrow.bsc.billing.connector.specification.fundaccounttransfer.r47.FundAccountTransferReloadSpecificationCommand]:Finishing the FundAccountTransferReloadSpecificationCommand execution (returnCode = 100). 2012-04-24 14:23:39,319:INFO :[http-0.0.0.0-8080-23]:[com.arrow.bsc.billing.connector.BillingConnector]:BSC_BILLING:RELOAD:END:TID=26746;MSISDN=3515956188;AMOUNT=10.0:0.546:NOK 2012-04-24 14:23:39,320:ERROR:[http-0.0.0.0-8080-23]:[com.arrow.bsc.BillingConnectorManager]:BSC:RELOAD:FAILED:TID=26746;MSISDN=3515956188:AMOUNT=10.0:REASON:Generic error Billing error code is [100] 2012-04-24 14:23:39,320:INFO :[http-0.0.0.0-8080-23]:[com.arrow.bsc.BillingConnectorManager]:BSC:RELOAD:END:TID=26746;MSISDN=3515956188;AMOUNT=10.0:0.562:NOK