30.08 10:21:20.101 INFO  [TextCustomerDisplayPluginAbstract] Screen updated:
30.08 10:21:20.101 INFO  [TextCustomerDisplayPluginAbstract] **********************
30.08 10:21:20.101 INFO  [TextCustomerDisplayPluginAbstract] *Добро               *
30.08 10:21:20.102 INFO  [TextCustomerDisplayPluginAbstract] *пожаловать          *
30.08 10:21:20.102 INFO  [TextCustomerDisplayPluginAbstract] **********************
30.08 10:21:20.102 INFO  [TextCustomerDisplayPluginAbstract]
30.08 10:21:20.224 INFO  [TechProcessImpl] eventControlKey: ControlKey [scanCode=27, command=kbdCancel]
30.08 10:21:20.423 INFO  [TechProcessImpl] eventControlKey: ControlKey [scanCode=27, command=kbdCancel]
30.08 10:21:20.584 INFO  [TechProcessImpl] eventControlKey: ControlKey [scanCode=27, command=kbdCancel]
30.08 10:21:22.210 INFO  [TechProcessImpl] eventBarcodeScanner SK79967334425208
30.08 10:21:22.210 INFO  [CheckContainer] Barcode SK79967334425208 has been received by visualisation
30.08 10:21:22.258 INFO  [TechProcessImpl] TP searchProduct 5000001
30.08 10:21:22.259 INFO  [CatalogService] getGoodsByBarCode barcode = 5000001
30.08 10:21:22.266 INFO  [CatalogService] get product by barcode '5000001' result: null
30.08 10:21:22.266 INFO  [SpeedLog] CatalogGoods: dataFinder.getProductByBarcode, barcode = 5000001 time = 7 ms
30.08 10:21:22.266 INFO  [SpeedLog] CatalogGoods#getGoodsByBarCode, barcode = 5000001 time = 7 ms
30.08 10:21:22.267 INFO  [CatalogService] Get product by item '5000001' result null
30.08 10:21:22.267 INFO  [SpeedLog] searchProduct time  time = 8 ms
30.08 10:21:22.268 INFO  [TechProcessImpl] TP searchProduct 01001
30.08 10:21:22.269 INFO  [CatalogService] Get product by item '01001' result ProductPieceEntity[name=Кефир малиновый сладкий (Израиль), item=01001]
30.08 10:21:22.274 INFO  [SpeedLog] getProductRestrictions  time = 5 ms
30.08 10:21:22.274 INFO  [SpeedLog] searchProduct time  time = 6 ms
30.08 10:21:22.285 INFO  [TechProcessImpl] TP searchProduct 5000002
30.08 10:21:22.289 INFO  [CatalogService] getGoodsByBarCode barcode = 5000002
30.08 10:21:22.292 INFO  [CatalogService] get product by barcode '5000002' result: null
30.08 10:21:22.293 INFO  [SpeedLog] CatalogGoods: dataFinder.getProductByBarcode, barcode = 5000002 time = 4 ms
30.08 10:21:22.293 INFO  [SpeedLog] CatalogGoods#getGoodsByBarCode, barcode = 5000002 time = 4 ms
30.08 10:21:22.293 INFO  [CatalogService] Get product by item '5000002' result null
30.08 10:21:22.293 INFO  [SpeedLog] searchProduct time  time = 4 ms
30.08 10:21:22.294 INFO  [TechProcessImpl] TP searchProduct 02025
30.08 10:21:22.295 INFO  [CatalogService] Get product by item '02025' result ProductPieceEntity[name=Пряник виноградный сладкий (Испания), item=02025]
30.08 10:21:22.295 INFO  [SpeedLog] getProductRestrictions  time = 0 ms
30.08 10:21:22.296 INFO  [SpeedLog] searchProduct time  time = 2 ms
30.08 10:21:22.307 INFO  [TechProcessImpl] TP searchProduct 5000002
30.08 10:21:22.307 INFO  [CatalogService] getGoodsByBarCode barcode = 5000002
30.08 10:21:22.308 INFO  [CatalogService] get product by barcode '5000002' result: null
30.08 10:21:22.308 INFO  [SpeedLog] CatalogGoods: dataFinder.getProductByBarcode, barcode = 5000002 time = 1 ms
30.08 10:21:22.308 INFO  [SpeedLog] CatalogGoods#getGoodsByBarCode, barcode = 5000002 time = 1 ms
30.08 10:21:22.310 INFO  [CatalogService] Get product by item '5000002' result null
30.08 10:21:22.310 INFO  [SpeedLog] searchProduct time  time = 3 ms
30.08 10:21:22.310 INFO  [TechProcessImpl] TP searchProduct 020256
30.08 10:21:22.311 INFO  [CatalogService] Get product by item '020256' result null
30.08 10:21:22.311 INFO  [CatalogService] getGoodsByBarCode barcode = 020256
30.08 10:21:22.311 INFO  [CatalogService] get product by barcode '020256' result: null
30.08 10:21:22.312 INFO  [SpeedLog] CatalogGoods: dataFinder.getProductByBarcode, barcode = 020256 time = 1 ms
30.08 10:21:22.312 INFO  [SpeedLog] CatalogGoods#getGoodsByBarCode, barcode = 020256 time = 1 ms
30.08 10:21:22.312 INFO  [SpeedLog] searchProduct time  time = 2 ms
30.08 10:21:22.312 WARN  [SoftCheckService] Unable to find product by barcode = '5000002' or code = '020256'
30.08 10:21:22.406 DEBUG [TechProcessImpl] Server online mode
30.08 10:21:24.448 INFO  [TechProcessImpl] eventControlKey: ControlKey [scanCode=10, command=kbdEnter]
30.08 10:21:24.454 INFO  [TechProcessImpl] TechProcess add position id: null; number: 1; item: 01001; type: ProductPieceEntity; count: 2000; sum: 28846; sumDiscount: 0; dateTime: (NULL); num-in-original: null
30.08 10:21:24.490 INFO  [SpeedLog] TP addPosition time = 35 ms
30.08 10:21:24.491 INFO  [TechProcessImpl] TechProcess add position id: null; number: 1; item: 02025; type: ProductPieceEntity; count: 10000; sum: 328830; sumDiscount: 0; dateTime: (NULL); num-in-original: null
30.08 10:21:24.503 INFO  [TextCustomerDisplayPluginAbstract] Screen updated:
30.08 10:21:24.503 INFO  [TextCustomerDisplayPluginAbstract] **********************
30.08 10:21:24.503 INFO  [TextCustomerDisplayPluginAbstract] *Кефир малин 2 288.46*
30.08 10:21:24.504 INFO  [TextCustomerDisplayPluginAbstract] *Итого         288.46*
30.08 10:21:24.504 INFO  [TextCustomerDisplayPluginAbstract] **********************
30.08 10:21:24.504 INFO  [TextCustomerDisplayPluginAbstract]
30.08 10:21:24.523 INFO  [SpeedLog] TP addPosition time = 32 ms
30.08 10:21:24.559 TRACE [MLServiceImpl] entering isEnabled()
30.08 10:21:24.560 TRACE [MLServiceImpl] leaving isEnabled(). the result is: false
30.08 10:21:24.560 DEBUG [LoymaxCardPlugin] entering getCardInfo(ru.crystals.pos.cards.service.PluginCardSearchRequest@19b3a4a).
30.08 10:21:24.561 DEBUG [LoymaxCardPlugin] Coupon number length: 15
30.08 10:21:24.566 DEBUG [LoymaxCardPlugin] Card number length: 13 - not allowed
30.08 10:21:24.567 DEBUG [LoymaxCardPlugin] leaving getCardInfo(CardInfoSearchParams). The card [9905100100001] does not exist in the processing for sure
30.08 10:21:24.645 INFO  [RegistryImpl] Subscription URLs of module CARDS:
    JNP : jnp://172.29.17.105:1099
    HTTP : http://172.29.17.105:8090
30.08 10:21:24.645 INFO  [RegistryImpl] Try register SubscriptionURL - CARDS : JNP:jnp://172.29.17.105:1099
30.08 10:21:24.645 INFO  [RegistryImpl] Try register SubscriptionURL - CARDS : HTTP:http://172.29.17.105:8090
30.08 10:21:24.686 WARN  [BonusBalanceSupplier] Processing "ServerCardsApplication" has provided no bonus balance for card "9905100100001"
30.08 10:21:24.838 INFO  [TextCustomerDisplayPluginAbstract] Screen updated:
30.08 10:21:24.838 INFO  [TextCustomerDisplayPluginAbstract] **********************
30.08 10:21:24.838 INFO  [TextCustomerDisplayPluginAbstract] *Пряник ви 10 3288.30*
30.08 10:21:24.838 INFO  [TextCustomerDisplayPluginAbstract] *Итого        3576.76*
30.08 10:21:24.838 INFO  [TextCustomerDisplayPluginAbstract] **********************
30.08 10:21:24.839 INFO  [TextCustomerDisplayPluginAbstract]
30.08 10:21:24.931 TRACE [TechProcessImpl] entering applyClientRequisites(ClientEntity). The argument is: holder [ClientEntity [id=19627; guid=110769; deleted=false]]
30.08 10:21:24.931 TRACE [TechProcessImpl] leaving applyClientRequisites(ClientEntity). Cash template prohibits usage of personal-sensitive data to send e-receipt to a card-ho;der
30.08 10:21:28.168 INFO  [DocumentSender] ping = true
30.08 10:21:31.240 INFO  [TechProcessImpl] eventFunctionKey: FunctionKey [scanCode=32, command=kbdSubtotal]
30.08 10:21:31.252 INFO  [CommonLogger] busy = true
30.08 10:21:31.258 TRACE [TechProcessImpl] Start warn divide alco
30.08 10:21:31.259 TRACE [TechProcessImpl] End warn devide alco
30.08 10:21:31.265 INFO  [TechProcessImpl] goToDiscounts
30.08 10:21:31.298 INFO  [LoyalBridgeServiceImpl] --------------- begin discount calculation ---------------
30.08 10:21:31.309 INFO  [LoyalProductFinder] Time finding items (2) = 11 ms
30.08 10:21:31.309 INFO  [LoyalProductsConverter] Time searching loyal goods for 2 productItems = 11 ms
30.08 10:21:31.309 INFO  [LoyalCalculatorConverter] Time converting 2 positions = 0 ms
30.08 10:21:31.560 WARN  [LoyaltyRestrictionsServiceImpl] checkRestrictions: no limits received
30.08 10:21:31.561 INFO  [DoProcessing] ============ LoyalCalculation: doDiscount start ============
30.08 10:21:31.561 INFO  [DoProcessing] GeneralInteractionMethod: MAXIMUM_DISCOUNT
30.08 10:21:31.574 INFO  [DoProcessing] ============ LoyalCalculation: doDiscount success ============
30.08 10:21:31.593 INFO  [DoProcessing] ============ LoyalCalculation: doDiscount start ============
30.08 10:21:31.593 INFO  [DoProcessing] GeneralInteractionMethod: MAXIMUM_DISCOUNT
30.08 10:21:31.601 WARN  [AdvancedMessagesActionResult] Calculator returns empty result. Do not generate slips or messages
30.08 10:21:31.601 WARN  [AdvancedMessagesActionResult] Calculator returns empty result. Do not generate slips or messages
30.08 10:21:31.604 WARN  [AdvancedMessagesActionResult] Calculator returns empty result. Do not generate slips or messages
30.08 10:21:31.606 WARN  [AdvancedMessagesActionResult] Calculator returns empty result. Do not generate slips or messages
30.08 10:21:31.682 INFO  [DoProcessing] ============ LoyalCalculation: doDiscount success ============
30.08 10:21:31.683 ERROR [DefaultCurrencyHandler] roundEndPriceForSale(BigDecimal, long, long): failed to calc end price through exact sum [14423] using rounding mode: CEILING: result * count == 7212 * 2000 == 14424 what differs from the control (rounded already) end sum : 14423
30.08 10:21:31.683 ERROR [DefaultCurrencyHandler] roundEndPriceForSale(BigDecimal, long, long): failed to calc end price through exact sum [164415] using rounding mode: CEILING: result * count == 16442 * 10000 == 164420 what differs from the control (rounded already) end sum : 164415
30.08 10:21:31.684 INFO  [DoProcessing] ============ LoyalCalculation: doDiscount start ============
30.08 10:21:31.684 INFO  [DoProcessing] GeneralInteractionMethod: MAXIMUM_DISCOUNT
30.08 10:21:31.685 INFO  [DoProcessing] ============ LoyalCalculation: doDiscount success ============
30.08 10:21:31.687 ERROR [DefaultCurrencyHandler] roundEndPriceForSale(BigDecimal, long, long): failed to calc end price through exact sum [14423] using rounding mode: CEILING: result * count == 7212 * 2000 == 14424 what differs from the control (rounded already) end sum : 14423
30.08 10:21:31.687 ERROR [DefaultCurrencyHandler] roundEndPriceForSale(BigDecimal, long, long): failed to calc end price through exact sum [164415] using rounding mode: CEILING: result * count == 16442 * 10000 == 164420 what differs from the control (rounded already) end sum : 164415
30.08 10:21:31.688 ERROR [DefaultCurrencyHandler] roundEndPriceForSale(BigDecimal, long, long): failed to calc end price through exact sum [14423] using rounding mode: CEILING: result * count == 7212 * 2000 == 14424 what differs from the control (rounded already) end sum : 14423
30.08 10:21:31.688 ERROR [DefaultCurrencyHandler] roundEndPriceForSale(BigDecimal, long, long): failed to calc end price through exact sum [164415] using rounding mode: CEILING: result * count == 16442 * 10000 == 164420 what differs from the control (rounded already) end sum : 164415
30.08 10:21:31.689 INFO  [LoyalServiceImpl] Discount calculation (Purchase #6; Positions: 4
30.08 10:21:31.692 WARN  [LoyalServiceImpl] extractNonDiscountRelatedFields: the argument is NULL! Null will be returned!
30.08 10:21:31.727 INFO  [LoyalBridgeServiceImpl] Total time of discount calculation = 429 ms
30.08 10:21:31.727 INFO  [LoyalBridgeServiceImpl] ---------------- end discount calculation ----------------
30.08 10:21:31.739 INFO  [TextCustomerDisplayPluginAbstract] Screen updated:
30.08 10:21:31.740 INFO  [TextCustomerDisplayPluginAbstract] **********************
30.08 10:21:31.740 INFO  [TextCustomerDisplayPluginAbstract] *Скидка       1788.38*
30.08 10:21:31.740 INFO  [TextCustomerDisplayPluginAbstract] *Итого        1788.38*
30.08 10:21:31.740 INFO  [TextCustomerDisplayPluginAbstract] **********************
30.08 10:21:31.740 INFO  [TextCustomerDisplayPluginAbstract]
30.08 10:21:31.757 INFO  [SpeedLog] TechProcess discounts processing on cheque with 4 positions [sale] time = 492 ms
30.08 10:21:31.762 INFO  [CommonLogger] value = 178838
30.08 10:21:31.824 TRACE [TechProcessImpl] Start warn divide amount
30.08 10:21:31.825 INFO  [TechProcessImpl] goToPayments
30.08 10:21:31.831 INFO  [CheckContainer] startPayments() surcharge = 178838
30.08 10:21:31.850 INFO  [CheckContainer] isPaymentComplete = false
30.08 10:21:31.850 INFO  [CheckContainer] prevState = ADD_PAYMENT
30.08 10:21:31.850 INFO  [CheckContainer] paid = 0
30.08 10:21:31.850 INFO  [CheckContainer] surcharge = 178838
30.08 10:21:31.850 INFO  [CheckContainer] getPaymentFiscalizeError = NONE
30.08 10:21:31.850 INFO  [CheckContainer] Current payment container is ru.crystals.pos.visualization.payments.cash.CashPaymentContainer
30.08 10:21:31.876 INFO  [CommonLogger] busy = false
30.08 10:21:31.877 INFO  [SpeedLog] (SUBTOTAL) time = 0,625;
30.08 10:21:31.877 INFO  [CommonLogger] busy = false