Details

    • Type: Bug Bug
    • Status: Open
    • Priority: Major Major
    • Resolution: Unresolved
    • Affects Version/s: 3.1.2
    • Fix Version/s: None
    • Component/s: failover
    • Labels:
      None

      Description

      Session is lost after failover happens. I've enabled logging at FINE level, and found out that, when message like that happens (below) session will be lost

      [#|2012-05-06T21:34:55.711+0200|FINE|glassfish3.1.2|org.shoal.ha.cache.command|_ThreadID=190;_ThreadName=Thread-2;ClassName=org.shoal.ha.cache.impl.interceptor.CommandHandlerInterceptor;MethodName=onReceive;|/nuplays-web-seller: Received ReplicationFramePayloadCommand: contains 1 commands from instance1|#]
      [#|2012-05-06T21:34:55.714+0200|FINE|glassfish3.1.2|org.shoal.ha.cache.command|_ThreadID=190;_ThreadName=Thread-2;ClassName=org.shoal.ha.cache.impl.interceptor.CommandHandlerInterceptor;MethodName=onReceive;|/nuplays-web-seller: Received SaveCommand:33(3a4f10df08b56a160de21fd03794) from instance1|#]
      [#|2012-05-06T21:34:55.717+0200|FINE|glassfish3.1.2|org.shoal.ha.cache.command.save|_ThreadID=190;_ThreadName=Thread-2;ClassName=org.shoal.adapter.store.commands.SaveCommand;MethodName=execute;|/nuplays-web-sellerSaveCommand:33 received save_command for key = 3a4f10df08b56a160de21fd03794 from instance1; version = 7|#]
      [#|2012-05-06T21:34:55.718+0200|FINE|glassfish3.1.2|org.shoal.ha.cache.command.save|_ThreadID=190;_ThreadName=Thread-2;ClassName=org.shoal.ha.cache.impl.store.SimpleStoreableDataStoreEntryUpdater;MethodName=executeSave;|SimpleStoreableDataStoreEntryUpdater.executeSave. IGNORING ... entry = org.shoal.ha.cache.impl.store.DataStoreEntry@5358503a; entry.version = 8; cmd.version = 7|#]

      When I notice IGNORING in log messages I know that session is already lost.
      At the same time, the other instance is showing in log files

      [#|2012-05-06T21:34:55.703+0200|FINE|glassfish3.1.2|org.shoal.ha.cache.command.save|_ThreadID=202;_ThreadName=Thread-2;ClassName=org.shoal.adapter.store.commands.AbstractSaveCommand;MethodName=writeObject;|/nuplays-web-seller sending state for key = 3a4f10df08b56a160de21fd03794; version = 7; lastAccessedAt = 1336332844303; to instance2|#]

      [#|2012-05-06T21:34:55.704+0200|FINE|glassfish3.1.2|org.shoal.ha.cache.command.save|_ThreadID=202;_ThreadName=Thread-2;ClassName=org.shoal.adapter.store.commands.SaveCommand;MethodName=writeObject;|/nuplays-web-seller sending save_command for key = 3a4f10df08b56a160de21fd03794; version = 7; lastAccessedAt = 1336332844303; to instance2|#]

      [#|2012-05-06T21:34:55.716+0200|FINE|glassfish3.1.2|org.shoal.ha.cache.interceptor.transmit|_ThreadID=202;_ThreadName=Thread-2;ClassName=org.shoal.ha.cache.impl.interceptor.TransmitInterceptor;MethodName=onTransmit;|/nuplays-web-seller: TransmitInterceptor./nuplays-web-seller:onTransmit() Sent ReplicationFramePayloadCommand: contains 1 commands to instance2; size: 13201|#]

        Activity

        Hide
        mhankus added a comment -

        Session is decremented on sending side. Some more logs showing that version was decremented from 8 to 7 (after FOUND IN LOCAL CACHE).

        [#|2012-05-06T21:34:54.202+0200|FINE|glassfish3.1.2|org.shoal.ha.cache.command.save|_ThreadID=201;_ThreadName=Thread-2;ClassName=org.shoal.adapter.store.commands.AbstractSaveCom
        mand;MethodName=writeObject;|/nuplays-web-seller sending state for key = 3a4f10df08b56a160de21fd03794; version = 8; lastAccessedAt = 1336332893913; to instance2|#]

        [#|2012-05-06T21:34:54.204+0200|FINE|glassfish3.1.2|org.shoal.ha.cache.command.save|_ThreadID=201;_ThreadName=Thread-2;ClassName=org.shoal.adapter.store.commands.SaveCommand;Met
        hodName=writeObject;|/nuplays-web-seller sending save_command for key = 3a4f10df08b56a160de21fd03794; version = 8; lastAccessedAt = 1336332893913; to instance2|#]

        [#|2012-05-06T21:34:54.212+0200|FINE|glassfish3.1.2|org.shoal.ha.cache.interceptor.transmit|_ThreadID=201;_ThreadName=Thread-2;ClassName=org.shoal.ha.cache.impl.interceptor.Tran
        smitInterceptor;MethodName=onTransmit;|/nuplays-web-seller: TransmitInterceptor./nuplays-web-seller:onTransmit() Sent ReplicationFramePayloadCommand: contains 1 commands to inst
        ance2; size: 13627|#]

        [#|2012-05-06T21:34:55.534+0200|FINE|glassfish3.1.2|org.shoal.ha.cache.command.load_request|_ThreadID=188;_ThreadName=Thread-2;ClassName=org.shoal.ha.cache.impl.store.Replicated
        DataStore;MethodName=get;|/nuplays-web-seller: load(3a4f10df08b56a160de21fd03794); FOUND IN LOCAL CACHE!!|#]

        [#|2012-05-06T21:34:55.539+0200|FINE|glassfish3.1.2|org.shoal.ha.cache.command.load_request|_ThreadID=188;_ThreadName=Thread-2;ClassName=org.shoal.ha.cache.impl.store.Replicated
        DataStore;MethodName=get;|/nuplays-web-seller: load(3a4f10df08b56a160de21fd03794) Final result: SimpleMetadata{version=7, lastAccessTime=1336332844303, maxInactiveInterval=18000
        00, state.length=12432, state=SimpleMetadata->state-84_-19_0_5_115_114_0_53_111_114_103_46_103_108_97_115_115_102_105_115_104_46_119_101_98_46_104_97_46_115_101_115_115_105_111_110_46_109_97_110_97_103_101_109_101_110_116_46_70_117_108_108_72_65_83_101_115_115_105_111_110_72_76_71_-125_-73_120_111_24_2_0_0_119_33_0_31_111_114_103_46_103_108_97_115_115_102_105_115_104_46_109_97_105_110_46_119_101_98_46_104_97_58_51_46_49_46_50_120_114_0_53_111_114_103_46_103_108_97_115_115_102_105_115_104_46_119_101_98_46_104_97_46_115_101_115_115_105_111_110_46_109_97_110_97_103_101_109_101_110_116_46_66_97_115_101_72_65_83_101_115_115_105_111_110_-22_32_75_-60_-102_-8_-61_-40_3_0_2_90_0_14_112_101_114_115_105_115_116_101_110_116_70_108_97_103_76_0_8_117_115_101_114_78_97_109_101_116_0_18_76_106_97_118_97_47_108_97_110_103_47_83_116_114_105_110_103_59_119_33_0_31_111_114_103_46_103_108_97_115_115_102_105_115_104_46_109_97_105_110_46_119_101_98_46_104_97_58_51_46_49_46_50_120_114_0_43_111_114_103_46_97_112_97_99_104_101_46_99_97_116_97_108_105_110_97_46_115_101_115_115_105_111_110_46_83_116_97_110_100_97_114_100_83_101_115_115_105_111_110_126_62_89_94_-109_-97_117_102_3_0_12_74_0_12_99_114_101_97_116_105_111_110_84_105_109_101_90_0

        Show
        mhankus added a comment - Session is decremented on sending side. Some more logs showing that version was decremented from 8 to 7 (after FOUND IN LOCAL CACHE). [#|2012-05-06T21:34:54.202+0200|FINE|glassfish3.1.2|org.shoal.ha.cache.command.save|_ThreadID=201;_ThreadName=Thread-2;ClassName=org.shoal.adapter.store.commands.AbstractSaveCom mand;MethodName=writeObject;|/nuplays-web-seller sending state for key = 3a4f10df08b56a160de21fd03794; version = 8; lastAccessedAt = 1336332893913; to instance2|#] [#|2012-05-06T21:34:54.204+0200|FINE|glassfish3.1.2|org.shoal.ha.cache.command.save|_ThreadID=201;_ThreadName=Thread-2;ClassName=org.shoal.adapter.store.commands.SaveCommand;Met hodName=writeObject;|/nuplays-web-seller sending save_command for key = 3a4f10df08b56a160de21fd03794; version = 8; lastAccessedAt = 1336332893913; to instance2|#] [#|2012-05-06T21:34:54.212+0200|FINE|glassfish3.1.2|org.shoal.ha.cache.interceptor.transmit|_ThreadID=201;_ThreadName=Thread-2;ClassName=org.shoal.ha.cache.impl.interceptor.Tran smitInterceptor;MethodName=onTransmit;|/nuplays-web-seller: TransmitInterceptor./nuplays-web-seller:onTransmit() Sent ReplicationFramePayloadCommand: contains 1 commands to inst ance2; size: 13627|#] [#|2012-05-06T21:34:55.534+0200|FINE|glassfish3.1.2|org.shoal.ha.cache.command.load_request|_ThreadID=188;_ThreadName=Thread-2;ClassName=org.shoal.ha.cache.impl.store.Replicated DataStore;MethodName=get;|/nuplays-web-seller: load(3a4f10df08b56a160de21fd03794); FOUND IN LOCAL CACHE!!|#] [#|2012-05-06T21:34:55.539+0200|FINE|glassfish3.1.2|org.shoal.ha.cache.command.load_request|_ThreadID=188;_ThreadName=Thread-2;ClassName=org.shoal.ha.cache.impl.store.Replicated DataStore;MethodName=get;|/nuplays-web-seller: load(3a4f10df08b56a160de21fd03794) Final result: SimpleMetadata{version=7, lastAccessTime=1336332844303, maxInactiveInterval=18000 00, state.length=12432, state=SimpleMetadata->state-84_-19_0_5_115_114_0_53_111_114_103_46_103_108_97_115_115_102_105_115_104_46_119_101_98_46_104_97_46_115_101_115_115_105_111_110_46_109_97_110_97_103_101_109_101_110_116_46_70_117_108_108_72_65_83_101_115_115_105_111_110_72_76_71_-125_-73_120_111_24_2_0_0_119_33_0_31_111_114_103_46_103_108_97_115_115_102_105_115_104_46_109_97_105_110_46_119_101_98_46_104_97_58_51_46_49_46_50_120_114_0_53_111_114_103_46_103_108_97_115_115_102_105_115_104_46_119_101_98_46_104_97_46_115_101_115_115_105_111_110_46_109_97_110_97_103_101_109_101_110_116_46_66_97_115_101_72_65_83_101_115_115_105_111_110_-22_32_75_-60_-102_-8_-61_-40_3_0_2_90_0_14_112_101_114_115_105_115_116_101_110_116_70_108_97_103_76_0_8_117_115_101_114_78_97_109_101_116_0_18_76_106_97_118_97_47_108_97_110_103_47_83_116_114_105_110_103_59_119_33_0_31_111_114_103_46_103_108_97_115_115_102_105_115_104_46_109_97_105_110_46_119_101_98_46_104_97_58_51_46_49_46_50_120_114_0_43_111_114_103_46_97_112_97_99_104_101_46_99_97_116_97_108_105_110_97_46_115_101_115_115_105_111_110_46_83_116_97_110_100_97_114_100_83_101_115_115_105_111_110_126_62_89_94_-109_-97_117_102_3_0_12_74_0_12_99_114_101_97_116_105_111_110_84_105_109_101_90_0
        Hide
        mhankus added a comment -

        Logs form my previous comment, show that session is accessed concurrently (only readonly access).
        My application serves pictures (it needes to check if someone is logged in before sending pictures). So browser request 4-5 pictures at the same time.
        So _ThreadID=201 knows that version is 8, but _ThreadID=188 knows only about version 7. So probably threads overwrite some data structures,
        and session is lost.

        Show
        mhankus added a comment - Logs form my previous comment, show that session is accessed concurrently (only readonly access). My application serves pictures (it needes to check if someone is logged in before sending pictures). So browser request 4-5 pictures at the same time. So _ThreadID=201 knows that version is 8, but _ThreadID=188 knows only about version 7. So probably threads overwrite some data structures, and session is lost.

          People

          • Assignee:
            Mahesh Kannan
            Reporter:
            mhankus
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated: