[CAMEL-3650] SMSC initiated unbind spawns exponential amounts of reconnect threads - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Closed
Priority: Critical
Resolution: Fixed
Affects Version/s: 2.6.0
Fix Version/s: 2.7.0
Component/s: camel-smpp
Labels:
- smpp

Description

It took me a bit of time to put my finger on this problem.

When an unbind PDU is sent from the SMSC side to a camel-smpp endpoint, a cascading amount reconnect threads are spawned by the reconnect code. I can reliably re-produce this problem having a simple smpp consumer to a SMSC / simulator and issuing an unbind from the SMSC / simulator.

Here are some logs (I have added additional debug messages to the SmppConsumer to show the object references and state of the SmppSession objects):

2011-02-10 12:23:05,931 [ing.Main.main()] INFO  MainSupport          - Apache Camel 2.6.0 starting
2011-02-10 12:23:06,338 [ing.Main.main()] INFO  amelNamespaceHandler - OSGi environment not detected.
2011-02-10 12:23:06,338 [ing.Main.main()] DEBUG amelNamespaceHandler - Using org.apache.camel.spring.CamelContextFactoryBean as CamelContextBeanDefinitionParser
2011-02-10 12:23:06,764 [ing.Main.main()] DEBUG amelNamespaceHandler - Registered default: org.apache.camel.spring.CamelProducerTemplateFactoryBean with id: template on camel context: camelTestRouteBuilderContext
2011-02-10 12:23:06,764 [ing.Main.main()] DEBUG amelNamespaceHandler - Registered default: org.apache.camel.spring.CamelConsumerTemplateFactoryBean with id: consumerTemplate on camel context: camelTestRouteBuilderContext
2011-02-10 12:23:06,965 [ing.Main.main()] DEBUG SpringCamelContext   - Set the application context classloader to: java.net.URLClassLoader@16e7eec9
2011-02-10 12:23:06,984 [ing.Main.main()] DEBUG elContextFactoryBean - Found JAXB created routes: []
2011-02-10 12:23:06,990 [ing.Main.main()] DEBUG SpringCamelContext   - Adding routes from builder: Routes: []
2011-02-10 12:23:07,059 [ing.Main.main()] DEBUG SpringCamelContext   - onApplicationEvent: org.springframework.context.event.ContextRefreshedEvent[source=org.springframework.context.support.ClassPathXmlApplicationContext@4c9549af: startup date [Thu Feb 10 12:23:05 SAST 2011]; root of context hierarchy]
2011-02-10 12:23:07,059 [ing.Main.main()] INFO  SpringCamelContext   - Apache Camel 2.6.0 (CamelContext: camelTestRouteBuilderContext) is starting
2011-02-10 12:23:07,059 [ing.Main.main()] INFO  SpringCamelContext   - JMX enabled. Using ManagedManagementStrategy.
2011-02-10 12:23:07,106 [ing.Main.main()] DEBUG faultManagementAgent - Starting JMX agent on server: com.sun.jmx.mbeanserver.JmxMBeanServer@7e3b014c
2011-02-10 12:23:07,168 [ing.Main.main()] DEBUG faultManagementAgent - Registered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=context,name="camelTestRouteBuilderContext"
2011-02-10 12:23:07,194 [ing.Main.main()] DEBUG faultManagementAgent - Registered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=services,name=DefaultTypeConverter(0x61e481c1)
2011-02-10 12:23:07,194 [ing.Main.main()] DEBUG DefaultTypeConverter - Loading type converters ...
2011-02-10 12:23:07,194 [ing.Main.main()] INFO  nTypeConverterLoader - Loading file META-INF/services/org/apache/camel/TypeConverter to retrieve list of packages, from url: jar:file:/home/jacovt/.m2/repository/org/apache/camel/camel-core/2.6.0/camel-core-2.6.0.jar!/META-INF/services/org/apache/camel/TypeConverter
2011-02-10 12:23:07,195 [ing.Main.main()] INFO  nTypeConverterLoader - Loading file META-INF/services/org/apache/camel/TypeConverter to retrieve list of packages, from url: jar:file:/home/jacovt/.m2/repository/org/apache/activemq/activemq-camel/5.3.1-fuse-02-00/activemq-camel-5.3.1-fuse-02-00.jar!/META-INF/services/org/apache/camel/TypeConverter
2011-02-10 12:23:07,196 [ing.Main.main()] DEBUG ageScanClassResolver - Searching for annotations of org.apache.camel.Converter in packages: [org.apache.camel.component.file, org.apache.camel.component.bean, org.apache.camel.converter, org.apache.activemq.camel.converter]
2011-02-10 12:23:07,474 [ing.Main.main()] DEBUG ageScanClassResolver - Found: [class org.apache.camel.component.file.GenericFileConverter, class org.apache.camel.component.bean.BeanConverter, class org.apache.camel.converter.CamelConverter, class org.apache.camel.converter.CollectionConverter, class org.apache.camel.converter.IOConverter, class org.apache.camel.converter.NIOConverter, class org.apache.camel.converter.ObjectConverter, class org.apache.camel.converter.TimePatternConverter, class org.apache.camel.converter.jaxp.DomConverter, class org.apache.camel.converter.jaxp.StaxConverter, class org.apache.camel.converter.jaxp.StreamSourceConverter, class org.apache.camel.converter.jaxp.XmlConverter, class org.apache.camel.converter.stream.StreamCacheConverter, class org.apache.activemq.camel.converter.ActiveMQConverter, class org.apache.activemq.camel.converter.ActiveMQMessageConverter]
2011-02-10 12:23:07,474 [ing.Main.main()] INFO  nTypeConverterLoader - Found 4 packages with 15 @Converter classes to load
2011-02-10 12:23:07,474 [ing.Main.main()] DEBUG nTypeConverterLoader - Loading converter class: org.apache.camel.component.file.GenericFileConverter
2011-02-10 12:23:07,479 [ing.Main.main()] DEBUG nTypeConverterLoader - Loading converter class: org.apache.camel.component.bean.BeanConverter
2011-02-10 12:23:07,479 [ing.Main.main()] DEBUG nTypeConverterLoader - Loading converter class: org.apache.camel.converter.CamelConverter
2011-02-10 12:23:07,482 [ing.Main.main()] DEBUG nTypeConverterLoader - Loading converter class: org.apache.camel.converter.CollectionConverter
2011-02-10 12:23:07,483 [ing.Main.main()] DEBUG nTypeConverterLoader - Loading converter class: org.apache.camel.converter.IOConverter
2011-02-10 12:23:07,488 [ing.Main.main()] DEBUG nTypeConverterLoader - Loading converter class: org.apache.camel.converter.NIOConverter
2011-02-10 12:23:07,490 [ing.Main.main()] DEBUG nTypeConverterLoader - Loading converter class: org.apache.camel.converter.ObjectConverter
2011-02-10 12:23:07,491 [ing.Main.main()] DEBUG nTypeConverterLoader - Loading converter class: org.apache.camel.converter.TimePatternConverter
2011-02-10 12:23:07,491 [ing.Main.main()] DEBUG nTypeConverterLoader - Loading converter class: org.apache.camel.converter.jaxp.DomConverter
2011-02-10 12:23:07,492 [ing.Main.main()] DEBUG nTypeConverterLoader - Loading converter class: org.apache.camel.converter.jaxp.StaxConverter
2011-02-10 12:23:07,494 [ing.Main.main()] DEBUG nTypeConverterLoader - Loading converter class: org.apache.camel.converter.jaxp.StreamSourceConverter
2011-02-10 12:23:07,494 [ing.Main.main()] DEBUG nTypeConverterLoader - Loading converter class: org.apache.camel.converter.jaxp.XmlConverter
2011-02-10 12:23:07,499 [ing.Main.main()] DEBUG nTypeConverterLoader - Loading converter class: org.apache.camel.converter.stream.StreamCacheConverter
2011-02-10 12:23:07,499 [ing.Main.main()] DEBUG nTypeConverterLoader - Loading converter class: org.apache.activemq.camel.converter.ActiveMQConverter
2011-02-10 12:23:07,501 [ing.Main.main()] DEBUG nTypeConverterLoader - Loading converter class: org.apache.activemq.camel.converter.ActiveMQMessageConverter
2011-02-10 12:23:07,507 [ing.Main.main()] DEBUG DefaultTypeConverter - Loading type converters done
2011-02-10 12:23:07,508 [ing.Main.main()] INFO  DefaultTypeConverter - Loaded 150 type converters in 0.313 seconds
2011-02-10 12:23:07,516 [ing.Main.main()] DEBUG faultManagementAgent - Registered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=services,name=DefaultExecutorServiceStrategy(0x4d12ee4f)
2011-02-10 12:23:07,525 [ing.Main.main()] DEBUG faultManagementAgent - Registered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=services,name=SharedProducerServicePool(0x15dbac11)
2011-02-10 12:23:07,525 [ing.Main.main()] DEBUG dProducerServicePool - Starting service pool: org.apache.camel.impl.SharedProducerServicePool@15dbac11
2011-02-10 12:23:07,534 [ing.Main.main()] DEBUG faultManagementAgent - Registered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=services,name=DefaultInflightRepository(0xf7b650a)
2011-02-10 12:23:07,542 [ing.Main.main()] DEBUG faultManagementAgent - Registered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=services,name=DefaultShutdownStrategy(0x6e267b76)
2011-02-10 12:23:07,555 [ing.Main.main()] DEBUG ultComponentResolver - Found component: smpp via type: org.apache.camel.component.smpp.SmppComponent via: META-INF/services/org/apache/camel/component/smpp
2011-02-10 12:23:07,590 [ing.Main.main()] DEBUG faultManagementAgent - Registered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=components,name="smpp"
2011-02-10 12:23:07,591 [ing.Main.main()] DEBUG DefaultComponent     - Creating endpoint uri=[smpp://ubankmobile01@127.0.0.1:2775?amp%3BenquireLinkTimer=55000&amp%3BsystemType=ubankmobile01&amp%3BtransactionTimer=15000&password=u%24%40nk01], path=[ubankmobile01@127.0.0.1:2775], parameters=[{amp;enquireLinkTimer=55000, amp;systemType=ubankmobile01, amp;transactionTimer=15000, password=u$@nk01}]
2011-02-10 12:23:07,605 [ing.Main.main()] DEBUG SpringCamelContext   - smpp://ubankmobile01@127.0.0.1:2775?amp%3BenquireLinkTimer=55000&amp%3BsystemType=ubankmobile01&amp%3BtransactionTimer=15000&password=u%24%40nk01 converted to endpoint: Endpoint[smpp://ubankmobile01@127.0.0.1:2775?amp%3BenquireLinkTimer=55000&amp%3BsystemType=ubankmobile01&amp%3BtransactionTimer=15000&password=******] by component: org.apache.camel.component.smpp.SmppComponent@517c804b
2011-02-10 12:23:07,615 [ing.Main.main()] DEBUG faultManagementAgent - Registered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=endpoints,name="smpp://ubankmobile01@127.0.0.1:2775"
2011-02-10 12:23:07,655 [ing.Main.main()] DEBUG ultComponentResolver - Found component: log via type: org.apache.camel.component.log.LogComponent via: META-INF/services/org/apache/camel/component/log
2011-02-10 12:23:07,661 [ing.Main.main()] DEBUG faultManagementAgent - Registered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=components,name="log"
2011-02-10 12:23:07,661 [ing.Main.main()] DEBUG DefaultComponent     - Creating endpoint uri=[log://SmppIn], path=[SmppIn], parameters=[{}]
2011-02-10 12:23:07,666 [ing.Main.main()] DEBUG SpringCamelContext   - log://SmppIn converted to endpoint: Endpoint[log://SmppIn] by component: org.apache.camel.component.log.LogComponent@4633c1aa
2011-02-10 12:23:07,669 [ing.Main.main()] DEBUG faultManagementAgent - Registered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=endpoints,name="log://SmppIn"
2011-02-10 12:23:07,712 [ing.Main.main()] DEBUG faultManagementAgent - Registered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=tracer,name=Tracer(0x3761f888)
2011-02-10 12:23:07,747 [ing.Main.main()] DEBUG faultManagementAgent - Registered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=errorhandlers,name="DefaultErrorHandlerBuilder(ref:CamelDefaultErrorHandlerBuilder)"
2011-02-10 12:23:07,754 [ing.Main.main()] DEBUG SpringCamelContext   - Warming up route id: SmppConsumerRoute having autoStartup=true
2011-02-10 12:23:07,772 [ing.Main.main()] DEBUG faultManagementAgent - Registered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=services,name=ProducerCache(0x3a67ad79)
2011-02-10 12:23:07,774 [ing.Main.main()] DEBUG ProcessorEndpoint$1  - Starting producer: Producer[log://SmppIn]
2011-02-10 12:23:07,775 [ing.Main.main()] DEBUG ProducerCache        - Adding to producer cache with key: Endpoint[log://SmppIn] for producer: Producer[log://SmppIn]
2011-02-10 12:23:07,797 [ing.Main.main()] DEBUG faultManagementAgent - Registered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=threadpools,name=DefaultErrorHandler(0xa62b39f)
2011-02-10 12:23:07,797 [ing.Main.main()] DEBUG cutorServiceStrategy - Created new scheduled thread pool for source: DefaultErrorHandler[TraceInterceptor[To[log:SmppIn]]] with name: ErrorHandlerRedeliveryTask. [poolSize=10]. -> java.util.concurrent.ScheduledThreadPoolExecutor@55fe910c
2011-02-10 12:23:07,844 [ing.Main.main()] DEBUG faultManagementAgent - Registered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=processors,name="to1"
2011-02-10 12:23:07,873 [ing.Main.main()] DEBUG faultManagementAgent - Registered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=routes,name="SmppConsumerRoute"
2011-02-10 12:23:07,873 [ing.Main.main()] DEBUG SpringCamelContext   - Route: SmppConsumerRoute >>> EventDrivenConsumerRoute[Endpoint[smpp://ubankmobile01@127.0.0.1:2775?amp%3BenquireLinkTimer=55000&amp%3BsystemType=ubankmobile01&amp%3BtransactionTimer=15000&password=******] -> Instrumentation:route[UnitOfWork(Channel[sendTo(Endpoint[log://SmppIn])])]]
2011-02-10 12:23:07,873 [ing.Main.main()] DEBUG SpringCamelContext   - Starting consumer (order: 1000) on route: SmppConsumerRoute
2011-02-10 12:23:07,884 [ing.Main.main()] DEBUG faultManagementAgent - Registered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=consumers,name=SmppConsumer(0x59c27402)
2011-02-10 12:23:07,884 [ing.Main.main()] DEBUG SmppConsumer         - Connecting to: smpp://ubankmobile01@127.0.0.1:2775...
2011-02-10 12:23:07,884 [ing.Main.main()] DEBUG SmppConsumer         - Starting consumer: SmppConsumer[smpp://ubankmobile01@127.0.0.1:2775]
2011-02-10 12:23:07,922 [ing.Main.main()] DEBUG SMPPSession          - Connect and bind to 127.0.0.1 port 2775
2011-02-10 12:23:07,923 [ing.Main.main()] INFO  SMPPSession          - Connected
2011-02-10 12:23:07,923 [ing.Main.main()] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- CLOSED --> OPEN[org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:23:07,925 [Thread-6       ] INFO  SMPPSession          - Starting PDUReaderWorker with processor degree:3 ...
2011-02-10 12:23:10,913 [pool-1-thread-1] DEBUG stractSessionContext - Activity notified
2011-02-10 12:23:10,913 [pool-1-thread-1] DEBUG SMPPSessionOpen      - Bind Response header (30, 80000001, 00000000, 1)
2011-02-10 12:23:10,915 [ing.Main.main()] DEBUG AbstractSession      - bind response received
2011-02-10 12:23:10,915 [ing.Main.main()] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- OPEN --> BOUND_RX[org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:23:10,916 [ing.Main.main()] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: BOUND_RX
2011-02-10 12:23:10,916 [Thread-7       ] INFO  SMPPSession          - Starting EnquireLinkSender
2011-02-10 12:23:10,916 [ing.Main.main()] INFO  SmppConsumer         - Connected to: smpp://ubankmobile01@127.0.0.1:2775
2011-02-10 12:23:10,917 [ing.Main.main()] INFO  SpringCamelContext   - Route: SmppConsumerRoute started and consuming from: Endpoint[smpp://ubankmobile01@127.0.0.1:2775?amp%3BenquireLinkTimer=55000&amp%3BsystemType=ubankmobile01&amp%3BtransactionTimer=15000&password=******]
2011-02-10 12:23:10,918 [ing.Main.main()] DEBUG DefaultComponent     - Creating endpoint uri=[spring-event://default], path=[default], parameters=[{}]
2011-02-10 12:23:10,919 [ing.Main.main()] DEBUG SpringCamelContext   - spring-event://default converted to endpoint: Endpoint[spring-event://default] by component: org.apache.camel.component.event.EventComponent@774e1f2b
2011-02-10 12:23:10,925 [ing.Main.main()] DEBUG faultManagementAgent - Registered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=endpoints,name="spring-event://default"
2011-02-10 12:23:10,926 [ing.Main.main()] INFO  SpringCamelContext   - Total 1 routes, of which 1 is started.
2011-02-10 12:23:10,926 [ing.Main.main()] INFO  SpringCamelContext   - Apache Camel 2.6.0 (CamelContext: camelTestRouteBuilderContext) started in 3.866 seconds
2011-02-10 12:23:10,935 [ing.Main.main()] DEBUG MainSupport          - Starting Spring ApplicationContext: org.springframework.context.support.ClassPathXmlApplicationContext@4c9549af
2011-02-10 12:23:10,936 [ing.Main.main()] DEBUG SpringCamelContext   - onApplicationEvent: org.springframework.context.event.ContextStartedEvent[source=org.springframework.context.support.ClassPathXmlApplicationContext@4c9549af: startup date [Thu Feb 10 12:23:05 SAST 2011]; root of context hierarchy]
2011-02-10 12:23:11,408 [pool-1-thread-2] DEBUG stractSessionContext - Activity notified
2011-02-10 12:23:11,408 [pool-1-thread-2] DEBUG SMPPSession          - Sending enquire_link_resp
2011-02-10 12:23:16,413 [Thread-6       ] DEBUG SMPPSession          - No activity notified
2011-02-10 12:23:16,413 [Thread-6       ] DEBUG SMPPSession          - Sending enquire link notify
2011-02-10 12:23:18,851 [pool-1-thread-3] DEBUG stractSessionContext - Activity notified
2011-02-10 12:23:18,852 [Thread-7       ] DEBUG AbstractSession      - enquire_link response received
2011-02-10 12:23:23,853 [Thread-6       ] DEBUG SMPPSession          - No activity notified
2011-02-10 12:23:23,853 [Thread-6       ] DEBUG SMPPSession          - Sending enquire link notify
2011-02-10 12:23:24,854 [pool-1-thread-1] DEBUG stractSessionContext - Activity notified
2011-02-10 12:23:24,854 [Thread-7       ] DEBUG AbstractSession      - enquire_link response received
2011-02-10 12:23:29,859 [Thread-6       ] DEBUG SMPPSession          - No activity notified
2011-02-10 12:23:29,859 [Thread-6       ] DEBUG SMPPSession          - Sending enquire link notify
2011-02-10 12:23:30,938 [pool-1-thread-2] DEBUG stractSessionContext - Activity notified
2011-02-10 12:23:30,938 [Thread-7       ] DEBUG AbstractSession      - enquire_link response received
2011-02-10 12:23:35,943 [Thread-6       ] DEBUG SMPPSession          - No activity notified
2011-02-10 12:23:35,943 [Thread-6       ] DEBUG SMPPSession          - Sending enquire link notify
2011-02-10 12:23:37,901 [pool-1-thread-3] DEBUG stractSessionContext - Activity notified
2011-02-10 12:23:37,901 [Thread-7       ] DEBUG AbstractSession      - enquire_link response received
2011-02-10 12:23:42,906 [Thread-6       ] DEBUG SMPPSession          - No activity notified
2011-02-10 12:23:42,906 [Thread-6       ] DEBUG SMPPSession          - Sending enquire link notify
2011-02-10 12:23:45,256 [pool-1-thread-1] DEBUG stractSessionContext - Activity notified
2011-02-10 12:23:45,256 [Thread-7       ] DEBUG AbstractSession      - enquire_link response received
2011-02-10 12:23:50,261 [Thread-6       ] DEBUG SMPPSession          - No activity notified
2011-02-10 12:23:50,261 [Thread-6       ] DEBUG SMPPSession          - Sending enquire link notify
2011-02-10 12:23:51,232 [pool-1-thread-2] DEBUG stractSessionContext - Activity notified
2011-02-10 12:23:51,232 [Thread-7       ] DEBUG AbstractSession      - enquire_link response received
2011-02-10 12:23:56,237 [Thread-6       ] DEBUG SMPPSession          - No activity notified
2011-02-10 12:23:56,237 [Thread-6       ] DEBUG SMPPSession          - Sending enquire link notify
2011-02-10 12:23:57,208 [pool-1-thread-3] DEBUG stractSessionContext - Activity notified
2011-02-10 12:23:57,208 [Thread-7       ] DEBUG AbstractSession      - enquire_link response received
2011-02-10 12:24:02,211 [Thread-6       ] DEBUG SMPPSession          - No activity notified
2011-02-10 12:24:02,211 [Thread-6       ] DEBUG SMPPSession          - Sending enquire link notify
2011-02-10 12:24:03,277 [pool-1-thread-1] DEBUG stractSessionContext - Activity notified
2011-02-10 12:24:03,277 [Thread-7       ] DEBUG AbstractSession      - enquire_link response received
2011-02-10 12:24:08,281 [Thread-6       ] DEBUG SMPPSession          - No activity notified
2011-02-10 12:24:08,281 [Thread-6       ] DEBUG SMPPSession          - Sending enquire link notify
2011-02-10 12:24:09,436 [pool-1-thread-2] DEBUG stractSessionContext - Activity notified
2011-02-10 12:24:09,437 [Thread-7       ] DEBUG AbstractSession      - enquire_link response received
2011-02-10 12:24:09,821 [pool-1-thread-3] DEBUG stractSessionContext - Activity notified
2011-02-10 12:24:09,821 [pool-1-thread-3] INFO  ericSMPPSessionBound - Receving unbind request
2011-02-10 12:24:09,822 [pool-1-thread-3] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- BOUND_RX --> UNBOUND[org.jsmpp.session.SMPPSession@501b2cb9]

Everything is perfectly fine up to this point. It is here that the SMSC / simulator issues an unbind request towards the camel-smpp consumer.

2011-02-10 12:24:09,937 [Thread-7       ] INFO  SMPPSession          - EnquireLinkSender stop
2011-02-10 12:24:14,826 [Thread-6       ] DEBUG SMPPSession          - No activity notified
2011-02-10 12:24:14,827 [Thread-6       ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- UNBOUND --> CLOSED[org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:24:14,827 [Thread-6       ] WARN  SmppConsumer         - Loost connection to: smpp://ubankmobile01@127.0.0.1:2775 - trying to reconnect...
2011-02-10 12:24:14,827 [Thread-6       ] DEBUG SmppConsumer         - >>>>>>>>>> Closing SMPP session [org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:24:14,829 [Thread-8       ] INFO  SmppConsumer         - Schedule reconnect after 5000 millis
2011-02-10 12:24:19,829 [Thread-8       ] INFO  SmppConsumer         - Trying to reconnect to smpp://ubankmobile01@127.0.0.1:2775 - attempt #1...
2011-02-10 12:24:19,830 [Thread-8       ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:19,830 [Thread-8       ] DEBUG SMPPSession          - Connect and bind to 127.0.0.1 port 2775
2011-02-10 12:24:19,830 [Thread-8       ] INFO  SMPPSession          - Connected
2011-02-10 12:24:19,830 [Thread-8       ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- CLOSED --> OPEN[org.jsmpp.session.SMPPSession@1b6b7f83]
2011-02-10 12:24:19,831 [Thread-9       ] INFO  SMPPSession          - Starting PDUReaderWorker with processor degree:3 ...
2011-02-10 12:24:22,834 [pool-2-thread-1] DEBUG stractSessionContext - Activity notified
2011-02-10 12:24:22,834 [pool-2-thread-1] DEBUG SMPPSessionOpen      - Bind Response header (30, 80000001, 0000000d, 1)
2011-02-10 12:24:22,835 [Thread-8       ] DEBUG AbstractSession      - bind response received
2011-02-10 12:24:22,837 [Thread-8       ] ERROR SMPPSession          - Receive negative bind response
org.jsmpp.extra.NegativeResponseException: Negative response 0000000d found
	at org.jsmpp.session.AbstractSession.validateResponse(AbstractSession.java:215)
	at org.jsmpp.session.AbstractSession.executeSendCommand(AbstractSession.java:271)
	at org.jsmpp.session.SMPPSession.sendBind(SMPPSession.java:294)
	at org.jsmpp.session.SMPPSession.connectAndBind(SMPPSession.java:232)
	at org.jsmpp.session.SMPPSession.connectAndBind(SMPPSession.java:200)
	at org.apache.camel.component.smpp.SmppConsumer.createSession(SmppConsumer.java:161)
	at org.apache.camel.component.smpp.SmppConsumer.access$500(SmppConsumer.java:54)
	at org.apache.camel.component.smpp.SmppConsumer$3.run(SmppConsumer.java:223)
2011-02-10 12:24:22,838 [Thread-8       ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- OPEN --> CLOSED[org.jsmpp.session.SMPPSession@1b6b7f83]

The above negative bind responseis due to the fact that only a single smpp RX bind is allowed to the SMSC / simulator. I suspect the underlying problem is how the exception is handled here, but I might be wrong.

2011-02-10 12:24:22,838 [Thread-8       ] WARN  SmppConsumer         - Loost connection to: smpp://ubankmobile01@127.0.0.1:2775 - trying to reconnect...
2011-02-10 12:24:22,838 [Thread-8       ] DEBUG SmppConsumer         - >>>>>>>>>> Closing SMPP session [org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:24:22,838 [Thread-10      ] INFO  SmppConsumer         - Schedule reconnect after 5000 millis
2011-02-10 12:24:22,838 [Thread-8       ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:22,838 [Thread-8       ] INFO  SmppConsumer         - Failed to reconnect to smpp://ubankmobile01@127.0.0.1:2775, sessionState == CLOSED
2011-02-10 12:24:22,838 [Thread-9       ] INFO  SMPPSession          - PDUReaderWorker stop
2011-02-10 12:24:22,838 [Thread-8       ] DEBUG SmppConsumer         - >>>>>>>>>> Closing SMPP session [org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:24:27,838 [Thread-10      ] INFO  SmppConsumer         - Trying to reconnect to smpp://ubankmobile01@127.0.0.1:2775 - attempt #1...
2011-02-10 12:24:27,839 [Thread-10      ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:27,839 [Thread-10      ] DEBUG SMPPSession          - Connect and bind to 127.0.0.1 port 2775
2011-02-10 12:24:27,839 [Thread-8       ] INFO  SmppConsumer         - Trying to reconnect to smpp://ubankmobile01@127.0.0.1:2775 - attempt #2...
2011-02-10 12:24:27,839 [Thread-8       ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:27,839 [Thread-10      ] INFO  SMPPSession          - Connected
2011-02-10 12:24:27,839 [Thread-8       ] DEBUG SMPPSession          - Connect and bind to 127.0.0.1 port 2775
2011-02-10 12:24:27,839 [Thread-10      ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- CLOSED --> OPEN[org.jsmpp.session.SMPPSession@62bc184]
2011-02-10 12:24:27,840 [Thread-11      ] INFO  SMPPSession          - Starting PDUReaderWorker with processor degree:3 ...
2011-02-10 12:24:27,840 [Thread-8       ] INFO  SMPPSession          - Connected
2011-02-10 12:24:27,840 [Thread-8       ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- CLOSED --> OPEN[org.jsmpp.session.SMPPSession@3e30e173]

OK, wait, we have 2 SMPPSession object references now? Seems like we have 2 Threads running that tries to re-connect...

2011-02-10 12:24:27,841 [Thread-12      ] INFO  SMPPSession          - Starting PDUReaderWorker with processor degree:3 ...
2011-02-10 12:24:31,035 [pool-3-thread-1] DEBUG stractSessionContext - Activity notified
2011-02-10 12:24:31,035 [pool-3-thread-1] DEBUG SMPPSessionOpen      - Bind Response header (30, 80000001, 0000000d, 1)
2011-02-10 12:24:31,035 [Thread-10      ] DEBUG AbstractSession      - bind response received
2011-02-10 12:24:31,035 [Thread-10      ] ERROR SMPPSession          - Receive negative bind response
org.jsmpp.extra.NegativeResponseException: Negative response 0000000d found
	at org.jsmpp.session.AbstractSession.validateResponse(AbstractSession.java:215)
	at org.jsmpp.session.AbstractSession.executeSendCommand(AbstractSession.java:271)
	at org.jsmpp.session.SMPPSession.sendBind(SMPPSession.java:294)
	at org.jsmpp.session.SMPPSession.connectAndBind(SMPPSession.java:232)
	at org.jsmpp.session.SMPPSession.connectAndBind(SMPPSession.java:200)
	at org.apache.camel.component.smpp.SmppConsumer.createSession(SmppConsumer.java:161)
	at org.apache.camel.component.smpp.SmppConsumer.access$500(SmppConsumer.java:54)
	at org.apache.camel.component.smpp.SmppConsumer$3.run(SmppConsumer.java:223)
2011-02-10 12:24:31,036 [Thread-10      ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- OPEN --> CLOSED[org.jsmpp.session.SMPPSession@62bc184]
2011-02-10 12:24:31,036 [Thread-10      ] WARN  SmppConsumer         - Loost connection to: smpp://ubankmobile01@127.0.0.1:2775 - trying to reconnect...
2011-02-10 12:24:31,036 [Thread-10      ] DEBUG SmppConsumer         - >>>>>>>>>> Closing SMPP session [org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:24:31,036 [Thread-10      ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:31,036 [Thread-10      ] INFO  SmppConsumer         - Failed to reconnect to smpp://ubankmobile01@127.0.0.1:2775, sessionState == CLOSED
2011-02-10 12:24:31,036 [Thread-11      ] INFO  SMPPSession          - PDUReaderWorker stop
2011-02-10 12:24:31,036 [Thread-10      ] DEBUG SmppConsumer         - >>>>>>>>>> Closing SMPP session [org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:24:31,037 [Thread-13      ] INFO  SmppConsumer         - Schedule reconnect after 5000 millis
2011-02-10 12:24:32,846 [Thread-12      ] DEBUG SMPPSession          - No activity notified
2011-02-10 12:24:32,982 [pool-4-thread-1] DEBUG stractSessionContext - Activity notified
2011-02-10 12:24:32,982 [pool-4-thread-1] DEBUG SMPPSessionOpen      - Bind Response header (30, 80000001, 0000000d, 1)
2011-02-10 12:24:32,982 [Thread-8       ] DEBUG AbstractSession      - bind response received
2011-02-10 12:24:32,982 [Thread-8       ] ERROR SMPPSession          - Receive negative bind response
org.jsmpp.extra.NegativeResponseException: Negative response 0000000d found
	at org.jsmpp.session.AbstractSession.validateResponse(AbstractSession.java:215)
	at org.jsmpp.session.AbstractSession.executeSendCommand(AbstractSession.java:271)
	at org.jsmpp.session.SMPPSession.sendBind(SMPPSession.java:294)
	at org.jsmpp.session.SMPPSession.connectAndBind(SMPPSession.java:232)
	at org.jsmpp.session.SMPPSession.connectAndBind(SMPPSession.java:200)
	at org.apache.camel.component.smpp.SmppConsumer.createSession(SmppConsumer.java:161)
	at org.apache.camel.component.smpp.SmppConsumer.access$500(SmppConsumer.java:54)
	at org.apache.camel.component.smpp.SmppConsumer$3.run(SmppConsumer.java:223)
2011-02-10 12:24:32,982 [Thread-8       ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- OPEN --> CLOSED[org.jsmpp.session.SMPPSession@3e30e173]
2011-02-10 12:24:32,982 [Thread-8       ] WARN  SmppConsumer         - Loost connection to: smpp://ubankmobile01@127.0.0.1:2775 - trying to reconnect...
2011-02-10 12:24:32,982 [Thread-8       ] DEBUG SmppConsumer         - >>>>>>>>>> Closing SMPP session [org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:24:32,983 [Thread-8       ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:32,983 [Thread-12      ] INFO  SMPPSession          - PDUReaderWorker stop
2011-02-10 12:24:32,983 [Thread-14      ] INFO  SmppConsumer         - Schedule reconnect after 5000 millis
2011-02-10 12:24:32,983 [Thread-8       ] INFO  SmppConsumer         - Failed to reconnect to smpp://ubankmobile01@127.0.0.1:2775, sessionState == CLOSED
2011-02-10 12:24:32,983 [Thread-8       ] DEBUG SmppConsumer         - >>>>>>>>>> Closing SMPP session [org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:24:36,037 [Thread-10      ] INFO  SmppConsumer         - Trying to reconnect to smpp://ubankmobile01@127.0.0.1:2775 - attempt #2...
2011-02-10 12:24:36,037 [Thread-13      ] INFO  SmppConsumer         - Trying to reconnect to smpp://ubankmobile01@127.0.0.1:2775 - attempt #1...

Some more re-connect threads...

2011-02-10 12:24:36,038 [Thread-10      ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:36,038 [Thread-13      ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:36,038 [Thread-10      ] DEBUG SMPPSession          - Connect and bind to 127.0.0.1 port 2775
2011-02-10 12:24:36,038 [Thread-13      ] DEBUG SMPPSession          - Connect and bind to 127.0.0.1 port 2775
2011-02-10 12:24:36,038 [Thread-10      ] INFO  SMPPSession          - Connected
2011-02-10 12:24:36,038 [Thread-13      ] INFO  SMPPSession          - Connected
2011-02-10 12:24:36,038 [Thread-10      ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- CLOSED --> OPEN[org.jsmpp.session.SMPPSession@782bbb7b]
2011-02-10 12:24:36,039 [Thread-13      ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- CLOSED --> OPEN[org.jsmpp.session.SMPPSession@7f21c5df]
2011-02-10 12:24:36,039 [Thread-15      ] INFO  SMPPSession          - Starting PDUReaderWorker with processor degree:3 ...
2011-02-10 12:24:36,039 [Thread-16      ] INFO  SMPPSession          - Starting PDUReaderWorker with processor degree:3 ...
2011-02-10 12:24:37,983 [Thread-14      ] INFO  SmppConsumer         - Trying to reconnect to smpp://ubankmobile01@127.0.0.1:2775 - attempt #1...
2011-02-10 12:24:37,984 [Thread-14      ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:37,984 [Thread-8       ] INFO  SmppConsumer         - Trying to reconnect to smpp://ubankmobile01@127.0.0.1:2775 - attempt #3...
2011-02-10 12:24:37,984 [Thread-8       ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:37,984 [Thread-14      ] DEBUG SMPPSession          - Connect and bind to 127.0.0.1 port 2775
2011-02-10 12:24:37,984 [Thread-8       ] DEBUG SMPPSession          - Connect and bind to 127.0.0.1 port 2775
2011-02-10 12:24:37,984 [Thread-14      ] INFO  SMPPSession          - Connected
2011-02-10 12:24:37,984 [Thread-8       ] INFO  SMPPSession          - Connected
2011-02-10 12:24:37,985 [Thread-14      ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- CLOSED --> OPEN[org.jsmpp.session.SMPPSession@6a754384]
2011-02-10 12:24:37,985 [Thread-8       ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- CLOSED --> OPEN[org.jsmpp.session.SMPPSession@38a3c5b6]
2011-02-10 12:24:37,985 [Thread-17      ] INFO  SMPPSession          - Starting PDUReaderWorker with processor degree:3 ...
2011-02-10 12:24:37,987 [Thread-18      ] INFO  SMPPSession          - Starting PDUReaderWorker with processor degree:3 ...
2011-02-10 12:24:38,831 [pool-6-thread-1] DEBUG stractSessionContext - Activity notified
2011-02-10 12:24:38,831 [pool-6-thread-1] DEBUG SMPPSessionOpen      - Bind Response header (30, 80000001, 0000000d, 1)
2011-02-10 12:24:38,831 [Thread-13      ] DEBUG AbstractSession      - bind response received
2011-02-10 12:24:38,831 [Thread-13      ] ERROR SMPPSession          - Receive negative bind response
org.jsmpp.extra.NegativeResponseException: Negative response 0000000d found
	at org.jsmpp.session.AbstractSession.validateResponse(AbstractSession.java:215)
	at org.jsmpp.session.AbstractSession.executeSendCommand(AbstractSession.java:271)
	at org.jsmpp.session.SMPPSession.sendBind(SMPPSession.java:294)
	at org.jsmpp.session.SMPPSession.connectAndBind(SMPPSession.java:232)
	at org.jsmpp.session.SMPPSession.connectAndBind(SMPPSession.java:200)
	at org.apache.camel.component.smpp.SmppConsumer.createSession(SmppConsumer.java:161)
	at org.apache.camel.component.smpp.SmppConsumer.access$500(SmppConsumer.java:54)
	at org.apache.camel.component.smpp.SmppConsumer$3.run(SmppConsumer.java:223)
2011-02-10 12:24:38,832 [Thread-13      ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- OPEN --> CLOSED[org.jsmpp.session.SMPPSession@7f21c5df]
2011-02-10 12:24:38,832 [Thread-13      ] WARN  SmppConsumer         - Loost connection to: smpp://ubankmobile01@127.0.0.1:2775 - trying to reconnect...
2011-02-10 12:24:38,832 [Thread-13      ] DEBUG SmppConsumer         - >>>>>>>>>> Closing SMPP session [org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:24:38,832 [Thread-13      ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:38,832 [Thread-19      ] INFO  SmppConsumer         - Schedule reconnect after 5000 millis
2011-02-10 12:24:38,832 [Thread-13      ] INFO  SmppConsumer         - Failed to reconnect to smpp://ubankmobile01@127.0.0.1:2775, sessionState == CLOSED
2011-02-10 12:24:38,832 [Thread-16      ] INFO  SMPPSession          - PDUReaderWorker stop
2011-02-10 12:24:38,833 [Thread-13      ] DEBUG SmppConsumer         - >>>>>>>>>> Closing SMPP session [org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:24:40,957 [pool-5-thread-1] DEBUG stractSessionContext - Activity notified
2011-02-10 12:24:40,957 [pool-5-thread-1] DEBUG SMPPSessionOpen      - Bind Response header (30, 80000001, 0000000d, 1)
2011-02-10 12:24:40,957 [Thread-10      ] DEBUG AbstractSession      - bind response received
2011-02-10 12:24:40,957 [Thread-10      ] ERROR SMPPSession          - Receive negative bind response
org.jsmpp.extra.NegativeResponseException: Negative response 0000000d found
	at org.jsmpp.session.AbstractSession.validateResponse(AbstractSession.java:215)
	at org.jsmpp.session.AbstractSession.executeSendCommand(AbstractSession.java:271)
	at org.jsmpp.session.SMPPSession.sendBind(SMPPSession.java:294)
	at org.jsmpp.session.SMPPSession.connectAndBind(SMPPSession.java:232)
	at org.jsmpp.session.SMPPSession.connectAndBind(SMPPSession.java:200)
	at org.apache.camel.component.smpp.SmppConsumer.createSession(SmppConsumer.java:161)
	at org.apache.camel.component.smpp.SmppConsumer.access$500(SmppConsumer.java:54)
	at org.apache.camel.component.smpp.SmppConsumer$3.run(SmppConsumer.java:223)
2011-02-10 12:24:40,958 [Thread-10      ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- OPEN --> CLOSED[org.jsmpp.session.SMPPSession@782bbb7b]
2011-02-10 12:24:40,958 [Thread-10      ] WARN  SmppConsumer         - Loost connection to: smpp://ubankmobile01@127.0.0.1:2775 - trying to reconnect...
2011-02-10 12:24:40,958 [Thread-10      ] DEBUG SmppConsumer         - >>>>>>>>>> Closing SMPP session [org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:24:40,958 [Thread-20      ] INFO  SmppConsumer         - Schedule reconnect after 5000 millis
2011-02-10 12:24:40,958 [Thread-15      ] INFO  SMPPSession          - PDUReaderWorker stop
2011-02-10 12:24:40,958 [Thread-10      ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:40,958 [Thread-10      ] INFO  SmppConsumer         - Failed to reconnect to smpp://ubankmobile01@127.0.0.1:2775, sessionState == CLOSED
2011-02-10 12:24:40,959 [Thread-10      ] DEBUG SmppConsumer         - >>>>>>>>>> Closing SMPP session [org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:24:42,821 [pool-8-thread-1] DEBUG stractSessionContext - Activity notified
2011-02-10 12:24:42,821 [pool-8-thread-1] DEBUG SMPPSessionOpen      - Bind Response header (30, 80000001, 0000000d, 1)
2011-02-10 12:24:42,821 [Thread-8       ] DEBUG AbstractSession      - bind response received
2011-02-10 12:24:42,822 [Thread-8       ] ERROR SMPPSession          - Receive negative bind response
org.jsmpp.extra.NegativeResponseException: Negative response 0000000d found
	at org.jsmpp.session.AbstractSession.validateResponse(AbstractSession.java:215)
	at org.jsmpp.session.AbstractSession.executeSendCommand(AbstractSession.java:271)
	at org.jsmpp.session.SMPPSession.sendBind(SMPPSession.java:294)
	at org.jsmpp.session.SMPPSession.connectAndBind(SMPPSession.java:232)
	at org.jsmpp.session.SMPPSession.connectAndBind(SMPPSession.java:200)
	at org.apache.camel.component.smpp.SmppConsumer.createSession(SmppConsumer.java:161)
	at org.apache.camel.component.smpp.SmppConsumer.access$500(SmppConsumer.java:54)
	at org.apache.camel.component.smpp.SmppConsumer$3.run(SmppConsumer.java:223)
2011-02-10 12:24:42,822 [Thread-8       ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- OPEN --> CLOSED[org.jsmpp.session.SMPPSession@38a3c5b6]
2011-02-10 12:24:42,822 [Thread-8       ] WARN  SmppConsumer         - Loost connection to: smpp://ubankmobile01@127.0.0.1:2775 - trying to reconnect...
2011-02-10 12:24:42,822 [Thread-8       ] DEBUG SmppConsumer         - >>>>>>>>>> Closing SMPP session [org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:24:42,822 [Thread-21      ] INFO  SmppConsumer         - Schedule reconnect after 5000 millis
2011-02-10 12:24:42,822 [Thread-8       ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:42,822 [Thread-8       ] INFO  SmppConsumer         - Failed to reconnect to smpp://ubankmobile01@127.0.0.1:2775, sessionState == CLOSED
2011-02-10 12:24:42,822 [Thread-18      ] INFO  SMPPSession          - PDUReaderWorker stop
2011-02-10 12:24:42,823 [Thread-8       ] DEBUG SmppConsumer         - >>>>>>>>>> Closing SMPP session [org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:24:42,988 [Thread-17      ] DEBUG SMPPSession          - No activity notified
2011-02-10 12:24:43,832 [Thread-19      ] INFO  SmppConsumer         - Trying to reconnect to smpp://ubankmobile01@127.0.0.1:2775 - attempt #1...
2011-02-10 12:24:43,833 [Thread-19      ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:43,833 [Thread-19      ] DEBUG SMPPSession          - Connect and bind to 127.0.0.1 port 2775
2011-02-10 12:24:43,833 [Thread-13      ] INFO  SmppConsumer         - Trying to reconnect to smpp://ubankmobile01@127.0.0.1:2775 - attempt #2...
2011-02-10 12:24:43,833 [Thread-13      ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:43,833 [Thread-19      ] INFO  SMPPSession          - Connected
2011-02-10 12:24:43,833 [Thread-13      ] DEBUG SMPPSession          - Connect and bind to 127.0.0.1 port 2775
2011-02-10 12:24:43,833 [Thread-19      ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- CLOSED --> OPEN[org.jsmpp.session.SMPPSession@18dd7404]
2011-02-10 12:24:43,834 [Thread-13      ] INFO  SMPPSession          - Connected
2011-02-10 12:24:43,834 [Thread-22      ] INFO  SMPPSession          - Starting PDUReaderWorker with processor degree:3 ...
2011-02-10 12:24:43,834 [Thread-13      ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- CLOSED --> OPEN[org.jsmpp.session.SMPPSession@53606bf5]
2011-02-10 12:24:43,835 [Thread-23      ] INFO  SMPPSession          - Starting PDUReaderWorker with processor degree:3 ...
2011-02-10 12:24:44,972 [pool-7-thread-1] DEBUG stractSessionContext - Activity notified
2011-02-10 12:24:44,972 [pool-7-thread-1] DEBUG SMPPSessionOpen      - Bind Response header (30, 80000001, 0000000d, 1)
2011-02-10 12:24:44,972 [Thread-14      ] DEBUG AbstractSession      - bind response received
2011-02-10 12:24:44,972 [Thread-14      ] ERROR SMPPSession          - Receive negative bind response
org.jsmpp.extra.NegativeResponseException: Negative response 0000000d found
	at org.jsmpp.session.AbstractSession.validateResponse(AbstractSession.java:215)
	at org.jsmpp.session.AbstractSession.executeSendCommand(AbstractSession.java:271)
	at org.jsmpp.session.SMPPSession.sendBind(SMPPSession.java:294)
	at org.jsmpp.session.SMPPSession.connectAndBind(SMPPSession.java:232)
	at org.jsmpp.session.SMPPSession.connectAndBind(SMPPSession.java:200)
	at org.apache.camel.component.smpp.SmppConsumer.createSession(SmppConsumer.java:161)
	at org.apache.camel.component.smpp.SmppConsumer.access$500(SmppConsumer.java:54)
	at org.apache.camel.component.smpp.SmppConsumer$3.run(SmppConsumer.java:223)
2011-02-10 12:24:44,972 [Thread-14      ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- OPEN --> CLOSED[org.jsmpp.session.SMPPSession@6a754384]
2011-02-10 12:24:44,973 [Thread-14      ] WARN  SmppConsumer         - Loost connection to: smpp://ubankmobile01@127.0.0.1:2775 - trying to reconnect...
2011-02-10 12:24:44,973 [Thread-14      ] DEBUG SmppConsumer         - >>>>>>>>>> Closing SMPP session [org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:24:44,973 [Thread-14      ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:44,973 [Thread-24      ] INFO  SmppConsumer         - Schedule reconnect after 5000 millis
2011-02-10 12:24:44,973 [Thread-17      ] INFO  SMPPSession          - PDUReaderWorker stop
2011-02-10 12:24:44,973 [Thread-14      ] INFO  SmppConsumer         - Failed to reconnect to smpp://ubankmobile01@127.0.0.1:2775, sessionState == CLOSED
2011-02-10 12:24:44,974 [Thread-14      ] DEBUG SmppConsumer         - >>>>>>>>>> Closing SMPP session [org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:24:45,958 [Thread-20      ] INFO  SmppConsumer         - Trying to reconnect to smpp://ubankmobile01@127.0.0.1:2775 - attempt #1...
2011-02-10 12:24:45,958 [Thread-20      ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:45,959 [Thread-20      ] DEBUG SMPPSession          - Connect and bind to 127.0.0.1 port 2775
2011-02-10 12:24:45,959 [Thread-10      ] INFO  SmppConsumer         - Trying to reconnect to smpp://ubankmobile01@127.0.0.1:2775 - attempt #3...
2011-02-10 12:24:45,959 [Thread-10      ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:45,959 [Thread-20      ] INFO  SMPPSession          - Connected
2011-02-10 12:24:45,959 [Thread-10      ] DEBUG SMPPSession          - Connect and bind to 127.0.0.1 port 2775
2011-02-10 12:24:45,959 [Thread-20      ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- CLOSED --> OPEN[org.jsmpp.session.SMPPSession@684be8b8]
2011-02-10 12:24:45,960 [Thread-10      ] INFO  SMPPSession          - Connected
2011-02-10 12:24:45,960 [Thread-25      ] INFO  SMPPSession          - Starting PDUReaderWorker with processor degree:3 ...
2011-02-10 12:24:45,960 [Thread-10      ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- CLOSED --> OPEN[org.jsmpp.session.SMPPSession@79b7d13e]
2011-02-10 12:24:45,960 [Thread-26      ] INFO  SMPPSession          - Starting PDUReaderWorker with processor degree:3 ...
2011-02-10 12:24:47,018 [pool-9-thread-1] DEBUG stractSessionContext - Activity notified
2011-02-10 12:24:47,018 [pool-9-thread-1] DEBUG SMPPSessionOpen      - Bind Response header (30, 80000001, 0000000d, 1)
2011-02-10 12:24:47,018 [Thread-19      ] DEBUG AbstractSession      - bind response received
2011-02-10 12:24:47,018 [Thread-19      ] ERROR SMPPSession          - Receive negative bind response
org.jsmpp.extra.NegativeResponseException: Negative response 0000000d found
	at org.jsmpp.session.AbstractSession.validateResponse(AbstractSession.java:215)
	at org.jsmpp.session.AbstractSession.executeSendCommand(AbstractSession.java:271)
	at org.jsmpp.session.SMPPSession.sendBind(SMPPSession.java:294)
	at org.jsmpp.session.SMPPSession.connectAndBind(SMPPSession.java:232)
	at org.jsmpp.session.SMPPSession.connectAndBind(SMPPSession.java:200)
	at org.apache.camel.component.smpp.SmppConsumer.createSession(SmppConsumer.java:161)
	at org.apache.camel.component.smpp.SmppConsumer.access$500(SmppConsumer.java:54)
	at org.apache.camel.component.smpp.SmppConsumer$3.run(SmppConsumer.java:223)
2011-02-10 12:24:47,018 [Thread-19      ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- OPEN --> CLOSED[org.jsmpp.session.SMPPSession@18dd7404]
2011-02-10 12:24:47,019 [Thread-19      ] WARN  SmppConsumer         - Loost connection to: smpp://ubankmobile01@127.0.0.1:2775 - trying to reconnect...
2011-02-10 12:24:47,019 [Thread-19      ] DEBUG SmppConsumer         - >>>>>>>>>> Closing SMPP session [org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:24:47,019 [Thread-19      ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:47,019 [Thread-19      ] INFO  SmppConsumer         - Failed to reconnect to smpp://ubankmobile01@127.0.0.1:2775, sessionState == CLOSED
2011-02-10 12:24:47,019 [Thread-22      ] INFO  SMPPSession          - PDUReaderWorker stop
2011-02-10 12:24:47,019 [Thread-19      ] DEBUG SmppConsumer         - >>>>>>>>>> Closing SMPP session [org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:24:47,020 [Thread-27      ] INFO  SmppConsumer         - Schedule reconnect after 5000 millis

Even more re-connect threads being spawned...

2011-02-10 12:24:47,823 [Thread-21      ] INFO  SmppConsumer         - Trying to reconnect to smpp://ubankmobile01@127.0.0.1:2775 - attempt #1...
2011-02-10 12:24:47,823 [Thread-21      ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:47,823 [Thread-21      ] DEBUG SMPPSession          - Connect and bind to 127.0.0.1 port 2775
2011-02-10 12:24:47,823 [Thread-8       ] INFO  SmppConsumer         - Trying to reconnect to smpp://ubankmobile01@127.0.0.1:2775 - attempt #4...
2011-02-10 12:24:47,823 [Thread-8       ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:47,823 [Thread-21      ] INFO  SMPPSession          - Connected
2011-02-10 12:24:47,823 [Thread-8       ] DEBUG SMPPSession          - Connect and bind to 127.0.0.1 port 2775
2011-02-10 12:24:47,823 [Thread-21      ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- CLOSED --> OPEN[org.jsmpp.session.SMPPSession@490eb6ae]
2011-02-10 12:24:47,824 [Thread-8       ] INFO  SMPPSession          - Connected
2011-02-10 12:24:47,824 [Thread-28      ] INFO  SMPPSession          - Starting PDUReaderWorker with processor degree:3 ...
2011-02-10 12:24:47,824 [Thread-8       ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- CLOSED --> OPEN[org.jsmpp.session.SMPPSession@3b4d82e1]
2011-02-10 12:24:47,825 [Thread-29      ] INFO  SMPPSession          - Starting PDUReaderWorker with processor degree:3 ...
2011-02-10 12:24:48,838 [Thread-23      ] DEBUG SMPPSession          - No activity notified
2011-02-10 12:24:48,962 [ool-10-thread-1] DEBUG stractSessionContext - Activity notified
2011-02-10 12:24:48,962 [ool-10-thread-1] DEBUG SMPPSessionOpen      - Bind Response header (30, 80000001, 0000000d, 1)
2011-02-10 12:24:48,962 [Thread-13      ] DEBUG AbstractSession      - bind response received
2011-02-10 12:24:48,962 [Thread-13      ] ERROR SMPPSession          - Receive negative bind response
org.jsmpp.extra.NegativeResponseException: Negative response 0000000d found
	at org.jsmpp.session.AbstractSession.validateResponse(AbstractSession.java:215)
	at org.jsmpp.session.AbstractSession.executeSendCommand(AbstractSession.java:271)
	at org.jsmpp.session.SMPPSession.sendBind(SMPPSession.java:294)
	at org.jsmpp.session.SMPPSession.connectAndBind(SMPPSession.java:232)
	at org.jsmpp.session.SMPPSession.connectAndBind(SMPPSession.java:200)
	at org.apache.camel.component.smpp.SmppConsumer.createSession(SmppConsumer.java:161)
	at org.apache.camel.component.smpp.SmppConsumer.access$500(SmppConsumer.java:54)
	at org.apache.camel.component.smpp.SmppConsumer$3.run(SmppConsumer.java:223)
2011-02-10 12:24:48,963 [Thread-13      ] DEBUG SmppConsumer         - >>>>>>>>>>>>>>>>>>> STATE CHANGE -- OPEN --> CLOSED[org.jsmpp.session.SMPPSession@53606bf5]
2011-02-10 12:24:48,963 [Thread-13      ] WARN  SmppConsumer         - Loost connection to: smpp://ubankmobile01@127.0.0.1:2775 - trying to reconnect...
2011-02-10 12:24:48,963 [Thread-13      ] DEBUG SmppConsumer         - >>>>>>>>>> Closing SMPP session [org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:24:48,963 [Thread-13      ] DEBUG SmppConsumer         - Session info: [org.jsmpp.session.SMPPSession@501b2cb9], session state: CLOSED
2011-02-10 12:24:48,963 [Thread-13      ] INFO  SmppConsumer         - Failed to reconnect to smpp://ubankmobile01@127.0.0.1:2775, sessionState == CLOSED
2011-02-10 12:24:48,963 [Thread-23      ] INFO  SMPPSession          - PDUReaderWorker stop
2011-02-10 12:24:48,963 [Thread-13      ] DEBUG SmppConsumer         - >>>>>>>>>> Closing SMPP session [org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:24:48,964 [Thread-30      ] INFO  SmppConsumer         - Schedule reconnect after 5000 millis
^C2011-02-10 12:24:49,726 [Thread-5       ] INFO  rt$HangupInterceptor - Received hang up - stopping the main instance.
2011-02-10 12:24:49,726 [Thread-5       ] INFO  MainSupport          - Apache Camel 2.6.0 stopping
2011-02-10 12:24:49,727 [Thread-5       ] DEBUG MainSupport          - Stopping Spring ApplicationContext: org.springframework.context.support.ClassPathXmlApplicationContext@4c9549af
2011-02-10 12:24:49,733 [Thread-5       ] DEBUG SpringCamelContext   - onApplicationEvent: org.springframework.context.event.ContextClosedEvent[source=org.springframework.context.support.ClassPathXmlApplicationContext@4c9549af: startup date [Thu Feb 10 12:23:05 SAST 2011]; root of context hierarchy]
2011-02-10 12:24:49,735 [Thread-5       ] DEBUG ledConnectionFactory - Stop the PooledConnectionFactory, number of connections in cache: 0
2011-02-10 12:24:49,736 [Thread-5       ] INFO  SpringCamelContext   - Apache Camel 2.6.0 (CamelContext:camelTestRouteBuilderContext) is shutting down
2011-02-10 12:24:49,737 [Thread-5       ] INFO  aultShutdownStrategy - Starting to graceful shutdown 1 routes (timeout 300 seconds)
2011-02-10 12:24:49,738 [Thread-5       ] DEBUG cutorServiceStrategy - Created new single thread pool for source: org.apache.camel.impl.DefaultShutdownStrategy@6e267b76 with name: ShutdownTask. -> java.util.concurrent.Executors$FinalizableDelegatedExecutorService@6ea53502
2011-02-10 12:24:49,742 [ - ShutdownTask] DEBUG aultShutdownStrategy - There are 1 routes to shutdown
2011-02-10 12:24:49,742 [ - ShutdownTask] DEBUG SmppConsumer         - Disconnecting from: smpp://ubankmobile01@127.0.0.1:2775...
2011-02-10 12:24:49,742 [ - ShutdownTask] DEBUG SmppConsumer         - Closing session: org.jsmpp.session.SMPPSession@501b2cb9
2011-02-10 12:24:49,742 [ - ShutdownTask] DEBUG SmppConsumer         - >>>>>>>>>> Closing SMPP session [org.jsmpp.session.SMPPSession@501b2cb9]
2011-02-10 12:24:49,742 [ - ShutdownTask] DEBUG SmppConsumer         - calling super.doStop()
2011-02-10 12:24:49,742 [ - ShutdownTask] DEBUG SmppConsumer         - Stopping consumer: SmppConsumer[smpp://ubankmobile01@127.0.0.1:2775]
2011-02-10 12:24:49,742 [ - ShutdownTask] DEBUG ProcessorEndpoint$1  - Stopping producer: Producer[log://SmppIn]
2011-02-10 12:24:49,743 [ - ShutdownTask] INFO  SmppConsumer         - Disconnected from: smpp://ubankmobile01@127.0.0.1:2775
2011-02-10 12:24:49,743 [ - ShutdownTask] DEBUG aultShutdownStrategy - Shutdown complete for: SmppConsumer[smpp://ubankmobile01@127.0.0.1:2775]
2011-02-10 12:24:49,743 [ - ShutdownTask] INFO  aultShutdownStrategy - Route: SmppConsumerRoute shutdown complete, was consuming from: Endpoint[smpp://ubankmobile01@127.0.0.1:2775?amp%3BenquireLinkTimer=55000&amp%3BsystemType=ubankmobile01&amp%3BtransactionTimer=15000&password=******]
2011-02-10 12:24:49,744 [Thread-5       ] INFO  aultShutdownStrategy - Graceful shutdown of 1 routes completed in 0 seconds
2011-02-10 12:24:49,745 [Thread-5       ] DEBUG faultManagementAgent - Unregistered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=routes,name="SmppConsumerRoute"
2011-02-10 12:24:49,745 [Thread-5       ] DEBUG faultManagementAgent - Unregistered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=consumers,name=SmppConsumer(0x59c27402)
2011-02-10 12:24:49,745 [Thread-5       ] DEBUG faultManagementAgent - Unregistered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=processors,name="to1"
2011-02-10 12:24:49,747 [Thread-5       ] DEBUG faultManagementAgent - Unregistered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=context,name="camelTestRouteBuilderContext"
2011-02-10 12:24:49,747 [Thread-5       ] DEBUG cutorServiceStrategy - ShutdownNow ExecutorService: java.util.concurrent.Executors$FinalizableDelegatedExecutorService@6ea53502
2011-02-10 12:24:49,747 [Thread-5       ] INFO  ltInflightRepository - Shutting down with no inflight exchanges.
2011-02-10 12:24:49,747 [Thread-5       ] DEBUG dProducerServicePool - Stopping service pool: org.apache.camel.impl.SharedProducerServicePool@15dbac11
2011-02-10 12:24:49,748 [Thread-5       ] DEBUG cutorServiceStrategy - ShutdownNow ExecutorService: java.util.concurrent.ScheduledThreadPoolExecutor@55fe910c
2011-02-10 12:24:49,748 [Thread-5       ] DEBUG faultManagementAgent - Unregistered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=threadpools,name=DefaultErrorHandler(0xa62b39f)
2011-02-10 12:24:49,749 [Thread-5       ] DEBUG faultManagementAgent - Unregistered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=components,name="smpp"
2011-02-10 12:24:49,749 [Thread-5       ] DEBUG faultManagementAgent - Unregistered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=endpoints,name="spring-event://default"
2011-02-10 12:24:49,749 [Thread-5       ] DEBUG faultManagementAgent - Unregistered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=services,name=DefaultExecutorServiceStrategy(0x4d12ee4f)
2011-02-10 12:24:49,749 [Thread-5       ] DEBUG faultManagementAgent - Unregistered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=endpoints,name="log://SmppIn"
2011-02-10 12:24:49,749 [Thread-5       ] DEBUG faultManagementAgent - Unregistered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=services,name=ProducerCache(0x3a67ad79)
2011-02-10 12:24:49,749 [Thread-5       ] DEBUG faultManagementAgent - Unregistered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=services,name=DefaultTypeConverter(0x61e481c1)
2011-02-10 12:24:49,749 [Thread-5       ] DEBUG faultManagementAgent - Unregistered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=services,name=SharedProducerServicePool(0x15dbac11)
2011-02-10 12:24:49,749 [Thread-5       ] DEBUG faultManagementAgent - Unregistered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=tracer,name=Tracer(0x3761f888)
2011-02-10 12:24:49,749 [Thread-5       ] DEBUG faultManagementAgent - Unregistered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=services,name=DefaultShutdownStrategy(0x6e267b76)
2011-02-10 12:24:49,749 [Thread-5       ] DEBUG faultManagementAgent - Unregistered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=components,name="log"
2011-02-10 12:24:49,750 [Thread-5       ] DEBUG faultManagementAgent - Unregistered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=services,name=DefaultInflightRepository(0xf7b650a)
2011-02-10 12:24:49,750 [Thread-5       ] DEBUG faultManagementAgent - Unregistered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=endpoints,name="smpp://ubankmobile01@127.0.0.1:2775"
2011-02-10 12:24:49,750 [Thread-5       ] DEBUG faultManagementAgent - Unregistered MBean with objectname: org.apache.camel:context=jacovt-notebook/camelTestRouteBuilderContext,type=errorhandlers,name="DefaultErrorHandlerBuilder(ref:CamelDefaultErrorHandlerBuilder)"
2011-02-10 12:24:49,750 [Thread-5       ] INFO  SpringCamelContext   - Uptime: 1 minute
2011-02-10 12:24:49,750 [Thread-5       ] INFO  SpringCamelContext   - Apache Camel 2.6.0 (CamelContext: camelTestRouteBuilderContext) is shutdown in 0.014 seconds

The above thread-spawning quickly gets out of hand with thousands being created.

Note however that this problem does not seem to happen when the smsc goes down (session is closed and a connection refused pops up), but only when an unbind happens and then a negative bind.

Attachments

Activity

People

Assignee:: Christian Müller

Reporter:: Jaco van Tonder

Votes:: 0 Vote for this issue

Watchers:: 0 Start watching this issue

Dates

Created:: 10/Feb/11 10:49

Updated:: 25/Oct/11 11:35

Resolved:: 28/Feb/11 18:42