11.10 17:55:41.486 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@5276338 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:41.486 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@5276338 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:41.486 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:41.486 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:41.486 INFO  [JDBCMapperImpl]
11.10 17:55:41.488 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@27537853 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:41.488 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@27537853 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:41.488 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:41.488 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:41.488 INFO  [JDBCMapperImpl]
11.10 17:55:43.419 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327624]; fileName: null; status: NO_SENT
11.10 17:55:43.419 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
SET sent_to_server_status = :status, filename = :fileName
WHERE id IN (:ids)
11.10 17:55:43.421 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 2 [ms]
11.10 17:55:43.421 TRACE [TransferManager] setStatus: [1] loy-txes were updated
11.10 17:55:43.421 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175540_408_73011_3.ser
11.10 17:55:43.422 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:55:43.422 INFO  [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
11.10 17:55:43.422 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:55:44.642 DEBUG [KeyboardImpl] -> KEY PRESSED: keyCode = 107
11.10 17:55:44.643 DEBUG [KeyboardImpl] -> KEY TYPED: keyCode = 107, keyChar +
11.10 17:55:44.643 DEBUG [KeyboardImpl] ---> KEY TYPED 2_1: keyCode = 43
11.10 17:55:44.663 DEBUG [KeyboardImpl] keyboard - keysqueue [[Key scanCode=43]]
11.10 17:55:44.712 DEBUG [KeyboardImpl] -> KEY RELEASED: keyCode = 107
11.10 17:55:45.337 DEBUG [KeyboardImpl] -> KEY PRESSED: keyCode = 32
11.10 17:55:45.337 DEBUG [KeyboardImpl] -> KEY TYPED: keyCode = 32, keyChar
11.10 17:55:45.337 DEBUG [KeyboardImpl] ---> KEY TYPED 3: keyCode = 32
11.10 17:55:45.360 DEBUG [KeyboardImpl] keyboard - keysqueue [[Key scanCode=32]]
11.10 17:55:45.361 INFO  [TechProcessImpl] eventFunctionKey: FunctionKey [scanCode=32, command=kbdSubtotal]
11.10 17:55:45.365 DEBUG [CheckContainer] CheckContainer.subtotal() - Check state: SEARCH_PRODUCT, State purchase: WAIT_GOODS
11.10 17:55:45.370 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@18246526 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.370 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@6557212 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.370 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@18246526 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.370 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.370 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.370 INFO  [JDBCMapperImpl]
11.10 17:55:45.370 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@11847117 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.371 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@15870878 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.371 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@11847117 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.371 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.371 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.371 INFO  [JDBCMapperImpl]
11.10 17:55:45.371 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@2483493 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.371 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@2168019 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.371 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@2483493 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.372 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.372 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.372 INFO  [JDBCMapperImpl]
11.10 17:55:45.372 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@12921527 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.372 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@20470058 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.372 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@12921527 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.372 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.373 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.373 INFO  [JDBCMapperImpl]
11.10 17:55:45.373 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@4428901 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.373 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@8691058 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.373 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@4428901 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.373 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.373 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.373 INFO  [JDBCMapperImpl]
11.10 17:55:45.374 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@17536263 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.374 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@6120581 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.374 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@17536263 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.374 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.376 DEBUG [KeyboardImpl] -> KEY RELEASED: keyCode = 32
11.10 17:55:45.376 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.376 INFO  [JDBCMapperImpl]
11.10 17:55:45.376 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@11740439 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.376 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@11164670 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.376 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@11740439 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.376 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.376 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.376 INFO  [JDBCMapperImpl]
11.10 17:55:45.377 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@18368257 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.377 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@6316715 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.377 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@18368257 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.377 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.377 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.377 INFO  [JDBCMapperImpl]
11.10 17:55:45.377 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@25588845 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.378 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@20166088 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.378 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@25588845 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.378 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.378 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.378 INFO  [JDBCMapperImpl]
11.10 17:55:45.378 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@5430624 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.378 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@27696443 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.378 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@5430624 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.378 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.378 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.378 INFO  [JDBCMapperImpl]
11.10 17:55:45.378 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@22002622 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.378 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@24172010 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.378 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@22002622 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.378 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.379 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.379 INFO  [JDBCMapperImpl]
11.10 17:55:45.379 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@18981753 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.379 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@10855971 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.379 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@18981753 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.379 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.379 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.379 INFO  [JDBCMapperImpl]
11.10 17:55:45.379 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@7956866 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.379 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@28388450 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.379 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@7956866 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.380 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.380 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.380 INFO  [JDBCMapperImpl]
11.10 17:55:45.380 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@33513478 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.380 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@16013668 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.380 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@33513478 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.380 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.381 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.381 INFO  [JDBCMapperImpl]
11.10 17:55:45.381 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@32904577 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.381 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@21429537 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.381 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@32904577 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.381 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.382 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.382 INFO  [JDBCMapperImpl]
11.10 17:55:45.382 DEBUG [SetApiGoodsPluginPaymentTypeLimiter] The purchase has no Set API goods
11.10 17:55:45.384 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@10308877 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.384 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@5248330 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.384 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@10308877 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.384 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.384 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.384 INFO  [JDBCMapperImpl]
11.10 17:55:45.384 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@26255615 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.384 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@8708708 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.385 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@26255615 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.385 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.385 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.385 INFO  [JDBCMapperImpl]
11.10 17:55:45.385 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@9385372 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.385 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@8622722 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.385 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@9385372 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.385 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.385 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.385 INFO  [JDBCMapperImpl]
11.10 17:55:45.385 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@3955701 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.385 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@28446100 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.385 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@3955701 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.385 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.386 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.386 INFO  [JDBCMapperImpl]
11.10 17:55:45.386 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@2685739 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.386 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@1407470 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.386 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@2685739 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.386 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.386 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.386 INFO  [JDBCMapperImpl]
11.10 17:55:45.386 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@686954 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.386 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@21169490 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.386 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@686954 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.386 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.387 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.387 INFO  [JDBCMapperImpl]
11.10 17:55:45.387 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@4933682 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.387 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@28220188 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.387 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@4933682 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.387 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.387 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.387 INFO  [JDBCMapperImpl]
11.10 17:55:45.387 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@4482664 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.387 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@30055143 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.387 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@4482664 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.387 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.387 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.387 INFO  [JDBCMapperImpl]
11.10 17:55:45.387 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@27022516 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.387 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@10964704 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.387 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@27022516 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.388 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.388 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.388 INFO  [JDBCMapperImpl]
11.10 17:55:45.388 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@32571706 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.388 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@6137025 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.388 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@32571706 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.388 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.388 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.388 INFO  [JDBCMapperImpl]
11.10 17:55:45.388 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@20931850 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.388 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@19004483 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.388 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@20931850 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.388 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.388 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.388 INFO  [JDBCMapperImpl]
11.10 17:55:45.388 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@8702860 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.388 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@24512881 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.389 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@8702860 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.389 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.389 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.389 INFO  [JDBCMapperImpl]
11.10 17:55:45.389 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@27602912 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.389 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@26743923 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.389 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@27602912 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.389 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.390 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.390 INFO  [JDBCMapperImpl]
11.10 17:55:45.390 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@30041255 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.390 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@6474478 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.390 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@30041255 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.390 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.390 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.390 INFO  [JDBCMapperImpl]
11.10 17:55:45.390 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@7356205 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.390 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@26513884 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.390 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@7356205 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.390 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.390 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.390 INFO  [JDBCMapperImpl]
11.10 17:55:45.390 DEBUG [SetApiGoodsPluginPaymentTypeLimiter] The purchase has no Set API goods
11.10 17:55:45.391 TRACE [CheckContainer] subtotalProcessPurchaseState: receipt state is: WAIT_GOODS
11.10 17:55:45.391 TRACE [CheckContainer] starting subtotal scenario...
11.10 17:55:45.391 INFO  [CommonLogger] busy = true
11.10 17:55:45.392 TRACE [TechProcessImpl] Start warn divide alco
11.10 17:55:45.392 TRACE [TechProcessImpl] End warn devide alco
11.10 17:55:45.396 INFO  [TechProcessImpl] goToDiscounts
11.10 17:55:45.423 INFO  [LoyalBridgeServiceImpl] --------------- begin discount calculation ---------------
11.10 17:55:45.423 TRACE [LoyalServiceImpl] entering doDiscount(PurchaseEntity)
11.10 17:55:45.423 TRACE [LoyalServiceImpl] entering doLoyalty(PurchaseEntity)
11.10 17:55:45.423 TRACE [CheckService] entering getExpectedDocNum()
11.10 17:55:45.423 TRACE [CheckService] the number of the last fiscalized document during the current shift is: 47
11.10 17:55:45.423 TRACE [CheckService] leaving getExpectedDocNum(). the result is: 48
11.10 17:55:45.428 INFO  [LoyalProductsConverter] Time searching loyal goods for 1 productItems = 5 ms
11.10 17:55:45.428 INFO  [LoyalCalculatorConverter] Time converting 1 positions = 0 ms
11.10 17:55:45.428 TRACE [MLServiceImpl] entering getMlCardNo(Purchase). The argument is: Purchase{number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, checkSum=3690, operationType=true, discountValueTotal=0}
11.10 17:55:45.428 TRACE [MLServiceImpl] leaving getMlCardNo(Purchase). The receipt does not have cards applied
11.10 17:55:45.428 TRACE [MLServiceImpl] entering getMlCouponNo(PurchaseEntity). The argument is: Purchase{number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, checkSum=3690, operationType=true, discountValueTotal=0}
11.10 17:55:45.428 TRACE [MLServiceImpl] leaving getMlCouponNo(PurchaseEntity). The receipt does not have cards applied
11.10 17:55:45.429 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
11.10 17:55:45.429 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.429+0300], manualActionGuids: []
11.10 17:55:45.429 TRACE [AdvActionsCacheImpl] leaving getActiveActions(Date, Set). The result is: [AdvertisingActionEntity{id=32427, guid=5661110, parentGuid=5660920, name='[SR-2906] - Печать внутри чека слипов лояльности акции Set10 с результатом "Реклама на чеке" — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3690.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32464, guid=4616066, parentGuid=4615424, name='МСК_УЦ_30%_на_товар_с_подходящим_сроком_годности', mode=AUTOMATIC, worksAnytime=false, useRestrictions=true, priority=3480.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32441, guid=361580, parentGuid=null, name='Лотерея ДР ВКТ  — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3770.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32571, guid=379822, parentGuid=5664429, name='Округление + безнал', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=3780.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32655, guid=5664571, parentGuid=5664487, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32599, guid=379860, parentGuid=379758, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}]; it took 0 [ms]
11.10 17:55:45.430 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
11.10 17:55:45.431 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.430+0300], manualActionGuids: []
11.10 17:55:45.432 TRACE [AdvActionsCacheImpl] leaving getActiveActions(Date, Set). The result is: [AdvertisingActionEntity{id=32427, guid=5661110, parentGuid=5660920, name='[SR-2906] - Печать внутри чека слипов лояльности акции Set10 с результатом "Реклама на чеке" — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3690.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32464, guid=4616066, parentGuid=4615424, name='МСК_УЦ_30%_на_товар_с_подходящим_сроком_годности', mode=AUTOMATIC, worksAnytime=false, useRestrictions=true, priority=3480.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32441, guid=361580, parentGuid=null, name='Лотерея ДР ВКТ  — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3770.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32571, guid=379822, parentGuid=5664429, name='Округление + безнал', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=3780.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32655, guid=5664571, parentGuid=5664487, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32599, guid=379860, parentGuid=379758, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}]; it took 1 [ms]
11.10 17:55:45.432 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
11.10 17:55:45.432 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.432+0300], manualActionGuids: []
11.10 17:55:45.432 TRACE [AdvActionsCacheImpl] leaving getActiveActions(Date, Set). The result is: [AdvertisingActionEntity{id=32427, guid=5661110, parentGuid=5660920, name='[SR-2906] - Печать внутри чека слипов лояльности акции Set10 с результатом "Реклама на чеке" — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3690.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32464, guid=4616066, parentGuid=4615424, name='МСК_УЦ_30%_на_товар_с_подходящим_сроком_годности', mode=AUTOMATIC, worksAnytime=false, useRestrictions=true, priority=3480.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32441, guid=361580, parentGuid=null, name='Лотерея ДР ВКТ  — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3770.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32571, guid=379822, parentGuid=5664429, name='Округление + безнал', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=3780.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32655, guid=5664571, parentGuid=5664487, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32599, guid=379860, parentGuid=379758, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}]; it took 0 [ms]
11.10 17:55:45.432 TRACE [LoyaltyRestrictionsServiceImpl] checkRestrictions: no client, internal card info: 'Not card'
11.10 17:55:45.432 INFO  [DoProcessing] ============ LoyalCalculation: doDiscount start ============
11.10 17:55:45.432 INFO  [DoProcessing] GeneralInteractionMethod: MAXIMUM_DISCOUNT
11.10 17:55:45.433 INFO  [DoProcessing] ============ LoyalCalculation: doDiscount success ============
11.10 17:55:45.434 TRACE [SCService] entering isEnabled()
11.10 17:55:45.434 TRACE [SCService] leaving isEnabled(). the result is: true
11.10 17:55:45.434 TRACE [SCService] entering calcDiscount(Purchase). The argument is: Purchase{number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, checkSum=3690, operationType=true, discountValueTotal=0}
11.10 17:55:45.435 TRACE [SCService] Send request <?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<ChequeRequest xmlns="http://smartcheckout.ru/xsd/s10ren.xsd" ChequeType="Soft">
    <RequestID>1570805730837</RequestID>
    <DateTime>2019-10-11T17:55:45.435+03:00</DateTime>
    <POS>3</POS>
    <Number>1570805730837</Number>
    <Summ>36.90</Summ>
    <Discount>0.000</Discount>
    <SummDiscounted>36.90</SummDiscounted>
    <Item>
        <PositionNumber>1</PositionNumber>
        <Article>1300386</Article>
        <ArticleName>Булочки Бородинские 300г п/п</ArticleName>
        <Price>36.90</Price>
        <Quantity>1.000</Quantity>
        <Summ>36.90</Summ>
        <Discount>0.000</Discount>
        <SummDiscounted>36.90</SummDiscounted>
    </Item>
</ChequeRequest>

11.10 17:55:45.435 TRACE [SCService] entering getServices()
11.10 17:55:45.435 TRACE [SCService] getting services (IN MEMORY)
11.10 17:55:45.435 TRACE [SCService] leaving getServices(). The result size is: 2
11.10 17:55:45.463 TRACE [SCService] Received response: <?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<ChequeRequestResponce xmlns="http://smartcheckout.ru/xsd/s10ren.xsd">
    <RequestID>1570805730837</RequestID>
    <Processed>2019-10-11T17:55:45.438+03:00</Processed>
    <ReturnCode>0</ReturnCode>
    <CashierMessageTO>0</CashierMessageTO>
    <Summ>36.90</Summ>
    <Discount>0.000</Discount>
    <SummDiscounted>36.90</SummDiscounted>
    <Item>
        <PositionNumber>1</PositionNumber>
        <Article>1300386</Article>
        <ArticleName>Булочки Бородинские 300г п/п</ArticleName>
        <Price>36.90</Price>
        <MinPrice>0</MinPrice>
        <Quantity>1.000</Quantity>
        <Summ>36.90</Summ>
        <Discount>0.000</Discount>
        <SummDiscounted>36.90</SummDiscounted>
    </Item>
</ChequeRequestResponce>

11.10 17:55:45.464 TRACE [SCReceiptConverter] ml discounts: {position-key [marking: 1300386; original-price: 3690]=0}
11.10 17:55:45.464 TRACE [SCReceiptConverter] it was inferred that no SC POS discounts were given on position [key: position-key [marking: 1300386; original-price: 3690]]: SC discount value is: 0
11.10 17:55:45.464 TRACE [SCService] leaving calcDiscount(Purchase). The result is: Purchase{number=null, dateCreate=null, checkSum=3690, operationType=null, discountValueTotal=0}; it took 30 [ms]
11.10 17:55:45.464 TRACE [MLServiceImpl] entering getMlCardNo(Purchase). The argument is: Purchase{number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, checkSum=3690, operationType=true, discountValueTotal=0}
11.10 17:55:45.464 TRACE [MLServiceImpl] leaving getMlCardNo(Purchase). The receipt does not have cards applied
11.10 17:55:45.464 TRACE [MLServiceImpl] entering getMlCouponNo(PurchaseEntity). The argument is: Purchase{number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, checkSum=3690, operationType=true, discountValueTotal=0}
11.10 17:55:45.464 TRACE [MLServiceImpl] leaving getMlCouponNo(PurchaseEntity). The receipt does not have cards applied
11.10 17:55:45.466 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
11.10 17:55:45.466 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.466+0300], manualActionGuids: []
11.10 17:55:45.466 TRACE [AdvActionsCacheImpl] leaving getActiveActions(Date, Set). The result is: [AdvertisingActionEntity{id=32427, guid=5661110, parentGuid=5660920, name='[SR-2906] - Печать внутри чека слипов лояльности акции Set10 с результатом "Реклама на чеке" — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3690.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32464, guid=4616066, parentGuid=4615424, name='МСК_УЦ_30%_на_товар_с_подходящим_сроком_годности', mode=AUTOMATIC, worksAnytime=false, useRestrictions=true, priority=3480.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32441, guid=361580, parentGuid=null, name='Лотерея ДР ВКТ  — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3770.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32571, guid=379822, parentGuid=5664429, name='Округление + безнал', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=3780.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32655, guid=5664571, parentGuid=5664487, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32599, guid=379860, parentGuid=379758, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}]; it took 0 [ms]
11.10 17:55:45.466 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
11.10 17:55:45.466 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.466+0300], manualActionGuids: []
11.10 17:55:45.466 TRACE [AdvActionsCacheImpl] leaving getActiveActions(Date, Set). The result is: [AdvertisingActionEntity{id=32427, guid=5661110, parentGuid=5660920, name='[SR-2906] - Печать внутри чека слипов лояльности акции Set10 с результатом "Реклама на чеке" — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3690.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32464, guid=4616066, parentGuid=4615424, name='МСК_УЦ_30%_на_товар_с_подходящим_сроком_годности', mode=AUTOMATIC, worksAnytime=false, useRestrictions=true, priority=3480.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32441, guid=361580, parentGuid=null, name='Лотерея ДР ВКТ  — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3770.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32571, guid=379822, parentGuid=5664429, name='Округление + безнал', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=3780.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32655, guid=5664571, parentGuid=5664487, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32599, guid=379860, parentGuid=379758, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}]; it took 0 [ms]
11.10 17:55:45.467 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
11.10 17:55:45.467 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.467+0300], manualActionGuids: []
11.10 17:55:45.468 TRACE [AdvActionsCacheImpl] leaving getActiveActions(Date, Set). The result is: [AdvertisingActionEntity{id=32427, guid=5661110, parentGuid=5660920, name='[SR-2906] - Печать внутри чека слипов лояльности акции Set10 с результатом "Реклама на чеке" — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3690.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32464, guid=4616066, parentGuid=4615424, name='МСК_УЦ_30%_на_товар_с_подходящим_сроком_годности', mode=AUTOMATIC, worksAnytime=false, useRestrictions=true, priority=3480.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32441, guid=361580, parentGuid=null, name='Лотерея ДР ВКТ  — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3770.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32571, guid=379822, parentGuid=5664429, name='Округление + безнал', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=3780.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32655, guid=5664571, parentGuid=5664487, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32599, guid=379860, parentGuid=379758, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}]; it took 1 [ms]
11.10 17:55:45.468 INFO  [DoProcessing] ============ LoyalCalculation: doDiscount start ============
11.10 17:55:45.468 INFO  [DoProcessing] GeneralInteractionMethod: MAXIMUM_DISCOUNT
11.10 17:55:45.468 INFO  [DoProcessing] ============ LoyalCalculation: doDiscount success ============
11.10 17:55:45.468 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
11.10 17:55:45.468 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.468+0300], manualActionGuids: []
11.10 17:55:45.468 TRACE [AdvActionsCacheImpl] leaving getActiveActions(Date, Set). The result is: [AdvertisingActionEntity{id=32427, guid=5661110, parentGuid=5660920, name='[SR-2906] - Печать внутри чека слипов лояльности акции Set10 с результатом "Реклама на чеке" — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3690.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32464, guid=4616066, parentGuid=4615424, name='МСК_УЦ_30%_на_товар_с_подходящим_сроком_годности', mode=AUTOMATIC, worksAnytime=false, useRestrictions=true, priority=3480.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32441, guid=361580, parentGuid=null, name='Лотерея ДР ВКТ  — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3770.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32571, guid=379822, parentGuid=5664429, name='Округление + безнал', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=3780.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32655, guid=5664571, parentGuid=5664487, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32599, guid=379860, parentGuid=379758, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}]; it took 0 [ms]
11.10 17:55:45.468 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
11.10 17:55:45.468 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.468+0300], manualActionGuids: []
11.10 17:55:45.468 TRACE [AdvActionsCacheImpl] leaving getActiveActions(Date, Set). The result is: [AdvertisingActionEntity{id=32427, guid=5661110, parentGuid=5660920, name='[SR-2906] - Печать внутри чека слипов лояльности акции Set10 с результатом "Реклама на чеке" — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3690.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32464, guid=4616066, parentGuid=4615424, name='МСК_УЦ_30%_на_товар_с_подходящим_сроком_годности', mode=AUTOMATIC, worksAnytime=false, useRestrictions=true, priority=3480.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32441, guid=361580, parentGuid=null, name='Лотерея ДР ВКТ  — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3770.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32571, guid=379822, parentGuid=5664429, name='Округление + безнал', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=3780.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32655, guid=5664571, parentGuid=5664487, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32599, guid=379860, parentGuid=379758, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}]; it took 0 [ms]
11.10 17:55:45.469 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
11.10 17:55:45.469 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.469+0300], manualActionGuids: []
11.10 17:55:45.469 TRACE [AdvActionsCacheImpl] leaving getActiveActions(Date, Set). The result is: [AdvertisingActionEntity{id=32427, guid=5661110, parentGuid=5660920, name='[SR-2906] - Печать внутри чека слипов лояльности акции Set10 с результатом "Реклама на чеке" — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3690.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32464, guid=4616066, parentGuid=4615424, name='МСК_УЦ_30%_на_товар_с_подходящим_сроком_годности', mode=AUTOMATIC, worksAnytime=false, useRestrictions=true, priority=3480.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32441, guid=361580, parentGuid=null, name='Лотерея ДР ВКТ  — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3770.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32571, guid=379822, parentGuid=5664429, name='Округление + безнал', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=3780.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32655, guid=5664571, parentGuid=5664487, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32599, guid=379860, parentGuid=379758, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}]; it took 0 [ms]
11.10 17:55:45.469 TRACE [LoyaltyRestrictionsServiceImpl] checkRestrictions: no client, internal card info: 'Not card'
11.10 17:55:45.469 INFO  [DoProcessing] ============ LoyalCalculation: doDiscount start ============
11.10 17:55:45.469 INFO  [DoProcessing] GeneralInteractionMethod: MAXIMUM_DISCOUNT
11.10 17:55:45.488 INFO  [DoProcessing] ============ LoyalCalculation: doDiscount success ============
11.10 17:55:45.488 DEBUG [SetApiPluginLoyProvider] No suitable Loyalty plugins found
11.10 17:55:45.488 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
11.10 17:55:45.488 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.488+0300], manualActionGuids: []
11.10 17:55:45.488 TRACE [AdvActionsCacheImpl] leaving getActiveActions(Date, Set). The result is: [AdvertisingActionEntity{id=32427, guid=5661110, parentGuid=5660920, name='[SR-2906] - Печать внутри чека слипов лояльности акции Set10 с результатом "Реклама на чеке" — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3690.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32464, guid=4616066, parentGuid=4615424, name='МСК_УЦ_30%_на_товар_с_подходящим_сроком_годности', mode=AUTOMATIC, worksAnytime=false, useRestrictions=true, priority=3480.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32441, guid=361580, parentGuid=null, name='Лотерея ДР ВКТ  — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3770.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32571, guid=379822, parentGuid=5664429, name='Округление + безнал', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=3780.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32655, guid=5664571, parentGuid=5664487, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32599, guid=379860, parentGuid=379758, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}]; it took 0 [ms]
11.10 17:55:45.489 TRACE [MLServiceImpl] entering getMlCardNo(Purchase). The argument is: Purchase{number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, checkSum=3690, operationType=true, discountValueTotal=0}
11.10 17:55:45.489 TRACE [MLServiceImpl] leaving getMlCardNo(Purchase). The receipt does not have cards applied
11.10 17:55:45.489 TRACE [MLServiceImpl] entering getMlCouponNo(PurchaseEntity). The argument is: Purchase{number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, checkSum=3690, operationType=true, discountValueTotal=0}
11.10 17:55:45.489 TRACE [MLServiceImpl] leaving getMlCouponNo(PurchaseEntity). The receipt does not have cards applied
11.10 17:55:45.489 DEBUG [DiscountCalculationListener] No suitable Loyalty plugins found to inform them about finishing discount calculation
11.10 17:55:45.489 INFO  [LoyalServiceImpl] Discount calculation (Purchase #48; Positions: 1
11.10 17:55:45.489 TRACE [LoyalServiceImpl] adjusting bonus discount ceilings of receipt: Purchase{number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, checkSum=3690, operationType=true, discountValueTotal=90}
11.10 17:55:45.489 DEBUG [LoyalServiceImpl] getAdvertisingActions.. number of manual actions = 0
11.10 17:55:45.489 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
11.10 17:55:45.489 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.489+0300], manualActionGuids: []
11.10 17:55:45.489 TRACE [AdvActionsCacheImpl] leaving getActiveActions(Date, Set). The result is: [AdvertisingActionEntity{id=32427, guid=5661110, parentGuid=5660920, name='[SR-2906] - Печать внутри чека слипов лояльности акции Set10 с результатом "Реклама на чеке" — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3690.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32464, guid=4616066, parentGuid=4615424, name='МСК_УЦ_30%_на_товар_с_подходящим_сроком_годности', mode=AUTOMATIC, worksAnytime=false, useRestrictions=true, priority=3480.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32441, guid=361580, parentGuid=null, name='Лотерея ДР ВКТ  — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3770.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32571, guid=379822, parentGuid=5664429, name='Округление + безнал', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=3780.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32655, guid=5664571, parentGuid=5664487, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32599, guid=379860, parentGuid=379758, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}]; it took 0 [ms]
11.10 17:55:45.489 DEBUG [LoyalServiceImpl] time of get active actions: 0
11.10 17:55:45.535 TRACE [LoyalServiceImpl] leaving doLoyalty(PurchaseEntity)
11.10 17:55:45.543 TRACE [LoyalServiceImpl] get manual advertising actions guids in purchase..
11.10 17:55:45.543 TRACE [LoyalServiceImpl] number of manual advertising actions guids in purchase = 0
11.10 17:55:45.543 DEBUG [LoyalServiceImpl] getAdvertisingActions.. number of manual actions = 0
11.10 17:55:45.543 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
11.10 17:55:45.543 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.543+0300], manualActionGuids: []
11.10 17:55:45.543 TRACE [AdvActionsCacheImpl] leaving getActiveActions(Date, Set). The result is: [AdvertisingActionEntity{id=32427, guid=5661110, parentGuid=5660920, name='[SR-2906] - Печать внутри чека слипов лояльности акции Set10 с результатом "Реклама на чеке" — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3690.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32464, guid=4616066, parentGuid=4615424, name='МСК_УЦ_30%_на_товар_с_подходящим_сроком_годности', mode=AUTOMATIC, worksAnytime=false, useRestrictions=true, priority=3480.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32441, guid=361580, parentGuid=null, name='Лотерея ДР ВКТ  — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3770.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32571, guid=379822, parentGuid=5664429, name='Округление + безнал', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=3780.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32655, guid=5664571, parentGuid=5664487, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32599, guid=379860, parentGuid=379758, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}]; it took 0 [ms]
11.10 17:55:45.543 DEBUG [LoyalServiceImpl] time of get active actions: 0
11.10 17:55:45.543 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@3649288 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.543 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@3649288 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.543 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.543 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.543 INFO  [JDBCMapperImpl]
11.10 17:55:45.544 TRACE [LoyalServiceImpl] entering extractNonDiscountRelatedFields(Long). The argument is: null
11.10 17:55:45.544 WARN  [LoyalServiceImpl] extractNonDiscountRelatedFields: the argument is NULL! Null will be returned!
11.10 17:55:45.544 TRACE [LoyalServiceImpl] leaving extractNonDiscountRelatedFields(Long). The result is: null; it took 0 [ms]
11.10 17:55:45.544 TRACE [LoyalServiceImpl] entering deleteLoyTransaction(Long). The argument is: null
11.10 17:55:45.544 TRACE [LoyalServiceImpl] leaving deleteLoyTransaction(Long). The result is: false
11.10 17:55:45.545 TRACE [LoyalServiceImpl] starting checkCouponsCountAndDeleteExcess(Purchase, int). The arguments are: purchase [Purchase{number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, checkSum=3690, operationType=true, discountValueTotal=90}], maxCountOfGeneratedCouponsInCheck = 0
11.10 17:55:45.545 TRACE [LoyalServiceImpl] leaving checkCouponsCountAndDeleteExcess(Purchase, int). maxCountOfGeneratedCouponsInCheck = 0 therefore we have no restriction
11.10 17:55:45.545 TRACE [LoyalCashConverter] Булочки Бородинские 300г п/п -   2 %
11.10 17:55:45.569 TRACE [CashAdvResultPersistenceManager] entering saveOrUpdate(LoyTransactionEntity). The arguments are: loyTransaction [loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]]
11.10 17:55:45.570 TRACE [HibernateBackedLoyTxDao] entering saveLoyTx(LoyTransactionEntity). The argument is: loyTx [loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]]
11.10 17:55:45.575 TRACE [HibernateBackedLoyTxDao] leaving saveLoyTx(LoyTransactionEntity). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 5 [ms]
11.10 17:55:45.579 TRACE [CashAdvResultPersistenceManager] leaving saveOrUpdate(LoyTransactionEntity). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 10 [ms]
11.10 17:55:45.579 INFO  [LoyalServiceImpl] Save processed purchase and discounts (Purchase #48; Number of positions: 1). Time: 34 ms.
11.10 17:55:45.579 TRACE [LoyalServiceImpl] leaving doDiscount(PurchaseEntity)
11.10 17:55:45.579 INFO  [LoyalBridgeServiceImpl] Total time of discount calculation = 156 ms
11.10 17:55:45.579 INFO  [LoyalBridgeServiceImpl] ---------------- end discount calculation ----------------
11.10 17:55:45.593 DEBUG [ChecksHandler] Setting check: PurchaseEntity [id=44672, number=null, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=null, fiscalDocNum=null, sentToServerStatus=NO_SENT]
11.10 17:55:45.594 TRACE [CheckPositionsListComponent] CheckPositionsListComponent.addPosition = id: 44682; number: 1; item: 1300386; type: ProductPieceEntity; count: 1000; sum: 3600; sumDiscount: 90; dateTime: 2019-10-11 17:55:30.848; num-in-original: null
11.10 17:55:45.595 INFO  [CommonLogger] value = 90
11.10 17:55:45.599 TRACE [HibernateBackedLoyTxDao] entering getLoyTxByReceipt(PurchaseEntity). The argument is: purchase  [PurchaseEntity [id=44672, number=null, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=null, fiscalDocNum=null, sentToServerStatus=NO_SENT]]
11.10 17:55:45.599 TRACE [HibernateBackedLoyTxDao] loy-tx-id of the receipt is not null: 327962
11.10 17:55:45.599 TRACE [HibernateBackedLoyTxDao] entering getLoyTxById(long). The argument is: loyTxId [327962]
11.10 17:55:45.601 TRACE [HibernateBackedLoyTxDao] 1 loy-txes were extracted
11.10 17:55:45.607 TRACE [HibernateBackedLoyTxDao] leaving getLoyTxById(long). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 8 [ms]
11.10 17:55:45.607 TRACE [HibernateBackedLoyTxDao] leaving getLoyTxByReceipt(PurchaseEntity). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 8 [ms]
11.10 17:55:45.608 TRACE [TechProcessImpl] Start warn divide amount
11.10 17:55:45.608 INFO  [TechProcessImpl] goToPayments
11.10 17:55:45.614 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@8942119 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.614 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@26587458 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.614 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@8942119 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.614 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.614 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.614 INFO  [JDBCMapperImpl]
11.10 17:55:45.614 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@28660136 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.614 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@6254306 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.615 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@28660136 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.615 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.615 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.615 INFO  [JDBCMapperImpl]
11.10 17:55:45.615 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@27736900 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.615 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@31366995 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.624 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@27736900 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.624 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.624 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.624 INFO  [JDBCMapperImpl]
11.10 17:55:45.624 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@15179985 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.624 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@16965713 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.624 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@15179985 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.625 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.625 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.625 INFO  [JDBCMapperImpl]
11.10 17:55:45.625 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@26315182 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.625 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@15775880 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.625 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@26315182 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.625 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.625 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.625 INFO  [JDBCMapperImpl]
11.10 17:55:45.625 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@27028399 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.625 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@32901349 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.625 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@27028399 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.625 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.625 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.625 INFO  [JDBCMapperImpl]
11.10 17:55:45.625 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@3484556 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.625 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@22209082 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.626 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@3484556 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.627 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.627 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.627 INFO  [JDBCMapperImpl]
11.10 17:55:45.627 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@19611436 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.627 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@1816140 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.627 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@19611436 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.627 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.627 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.627 INFO  [JDBCMapperImpl]
11.10 17:55:45.627 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@32873480 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.627 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@22869374 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.628 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@32873480 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.628 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.628 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.628 INFO  [JDBCMapperImpl]
11.10 17:55:45.628 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@17988902 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.628 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@2233374 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.628 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@17988902 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.628 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.628 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.628 INFO  [JDBCMapperImpl]
11.10 17:55:45.628 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@22599758 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.628 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@23143006 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.628 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@22599758 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.629 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.629 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.629 INFO  [JDBCMapperImpl]
11.10 17:55:45.629 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@29132185 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.629 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@16971284 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.629 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@29132185 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.629 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.629 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.629 INFO  [JDBCMapperImpl]
11.10 17:55:45.629 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@1955346 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.629 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@15365597 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.630 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@1955346 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.630 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.630 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.630 INFO  [JDBCMapperImpl]
11.10 17:55:45.630 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@20298452 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.630 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@17253808 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.630 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@20298452 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.630 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.630 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.630 INFO  [JDBCMapperImpl]
11.10 17:55:45.630 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@22455748 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.630 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@14116910 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name=?
11.10 17:55:45.630 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@22455748 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.631 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:45.631 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:45.631 INFO  [JDBCMapperImpl]
11.10 17:55:45.631 DEBUG [SetApiGoodsPluginPaymentTypeLimiter] The purchase has no Set API goods
11.10 17:55:45.631 DEBUG [CheckContainer] CheckContainer.startPayments()
11.10 17:55:45.631 DEBUG [CheckContainer] State in start payments = ADD_PAYMENT
11.10 17:55:45.631 DEBUG [CheckContainer] State purchase in start payments = PAYMENTS
11.10 17:55:45.632 INFO  [CheckContainer] startPayments() surcharge = 3600
11.10 17:55:45.661 DEBUG [Factory] CheckContainer.paymentTypeSelected(ru.crystals.pos.visualization.payments.cash.CashPaymentContainer@14fedad)
11.10 17:55:45.661 DEBUG [CheckContainer] /CheckContainer/ Trying to set state: ADD_PAYMENT
11.10 17:55:45.676 INFO  [CheckContainer] isPaymentComplete = false
11.10 17:55:45.677 INFO  [CheckContainer] prevState = ADD_POSITION
11.10 17:55:45.677 INFO  [CheckContainer] paid = 0
11.10 17:55:45.677 INFO  [CheckContainer] surcharge = 3600
11.10 17:55:45.677 INFO  [CheckContainer] getPaymentFiscalizeError = NONE
11.10 17:55:45.677 INFO  [CheckContainer] Current payment container is ru.crystals.pos.visualization.payments.cash.CashPaymentContainer
11.10 17:55:45.678 INFO  [CommonLogger] busy = false
11.10 17:55:45.678 INFO  [CommonLogger] busy = false
11.10 17:55:46.434 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327625]; fileName: null; status: NO_SENT
11.10 17:55:46.434 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
SET sent_to_server_status = :status, filename = :fileName
WHERE id IN (:ids)
11.10 17:55:46.436 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 2 [ms]
11.10 17:55:46.437 TRACE [TransferManager] setStatus: [1] loy-txes were updated
11.10 17:55:46.437 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175543_422_73011_3.ser
11.10 17:55:46.437 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:55:46.437 INFO  [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
11.10 17:55:46.437 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:55:46.926 DEBUG [HikariPool] HikariPool-4 - Pool stats (total=5, active=0, idle=5, waiting=0)
11.10 17:55:47.313 DEBUG [KeyboardImpl] -> KEY PRESSED: keyCode = 99
11.10 17:55:47.314 DEBUG [KeyboardImpl] -> KEY TYPED: keyCode = 99, keyChar 3
11.10 17:55:47.314 DEBUG [KeyboardImpl] ---> KEY TYPED 2_1: keyCode = 51
11.10 17:55:47.334 DEBUG [KeyboardImpl] keyboard - keysqueue [[Key scanCode=51]]
11.10 17:55:47.335 INFO  [TechProcessImpl] eventAlphaNumericKey: AlphaNumericKey [scanCode=51, character=3]
11.10 17:55:47.368 DEBUG [KeyboardImpl] -> KEY PRESSED: keyCode = 102
11.10 17:55:47.369 DEBUG [KeyboardImpl] -> KEY TYPED: keyCode = 102, keyChar 6
11.10 17:55:47.369 DEBUG [KeyboardImpl] ---> KEY TYPED 2_1: keyCode = 54
11.10 17:55:47.389 DEBUG [KeyboardImpl] keyboard - keysqueue [[Key scanCode=54]]
11.10 17:55:47.390 INFO  [TechProcessImpl] eventAlphaNumericKey: AlphaNumericKey [scanCode=54, character=6]
11.10 17:55:47.440 DEBUG [KeyboardImpl] -> KEY RELEASED: keyCode = 99
11.10 17:55:47.464 DEBUG [KeyboardImpl] -> KEY RELEASED: keyCode = 102
11.10 17:55:49.001 DEBUG [KeyboardImpl] -> KEY PRESSED: keyCode = 10
11.10 17:55:49.001 DEBUG [KeyboardImpl] -> KEY TYPED: keyCode = 10, keyChar

11.10 17:55:49.001 DEBUG [KeyboardImpl] ---> KEY TYPED 3: keyCode = 10
11.10 17:55:49.022 DEBUG [KeyboardImpl] keyboard - keysqueue [[Key scanCode=10]]
11.10 17:55:49.022 INFO  [TechProcessImpl] eventControlKey: ControlKey [scanCode=10, command=kbdEnter]
11.10 17:55:49.023 INFO  [CommonLogger] doProcessPayment() in class ru.crystals.pos.visualization.payments.cash.CashPaymentContainer
11.10 17:55:49.023 INFO  [TechProcessImpl] addPayment CashPaymentEntity 3600
11.10 17:55:49.038 TRACE [CheckService] last payment added feedbacks: []
11.10 17:55:49.038 TRACE [CheckService] feedbacks received: []
11.10 17:55:49.038 TRACE [TechProcessEventsImpl] entering purchaseChangedAtPaymentsStage(PurchaseEntity, List). The arguments are: purchase [PurchaseEntity [id=44672, number=null, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=null, fiscalDocNum=null, sentToServerStatus=NO_SENT]], notifications [[]]
11.10 17:55:49.038 TRACE [MainWindow] entering purchaseChangedAtPaymentsStage(PurchaseEntity, List). The arguments are: purchase [PurchaseEntity [id=44672, number=null, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=null, fiscalDocNum=null, sentToServerStatus=NO_SENT]], notifications [[]]
11.10 17:55:49.038 TRACE [MainWindow] updating receipt...
11.10 17:55:49.038 TRACE [MainWindow] entering MW.updateCheck(PurchaseEntity). The argument is: PurchaseEntity [id=44672, number=null, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=null, fiscalDocNum=null, sentToServerStatus=NO_SENT]
11.10 17:55:49.038 TRACE [MainWindow] MW.updateCheck(PurchaseEntity): visual state is: CHECK
11.10 17:55:49.038 DEBUG [CheckContainer] Updating check: PurchaseEntity [id=44672, number=null, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=null, fiscalDocNum=null, sentToServerStatus=NO_SENT]
11.10 17:55:49.041 TRACE [CheckPositionsListComponent] CheckPositionsListComponent.addPosition = id: 44682; number: 1; item: 1300386; type: ProductPieceEntity; count: 1000; sum: 3600; sumDiscount: 90; dateTime: 2019-10-11 17:55:30.848; num-in-original: null
11.10 17:55:49.052 INFO  [CommonLogger] value = 90
11.10 17:55:49.056 DEBUG [CheckContainer] CheckContainer.subtotal() - Check state: ADD_PAYMENT, State purchase: PAYMENTS
11.10 17:55:49.057 TRACE [MainWindow] leaving MW.updateCheck(PurchaseEntity)
11.10 17:55:49.057 TRACE [MainWindow] leaving purchaseChangedAtPaymentsStage(PurchaseEntity, List). It took 19 [ms]
11.10 17:55:49.057 TRACE [TechProcessEventsImpl] leaving purchaseChangedAtPaymentsStage(PurchaseEntity, List). It took 19 [ms]
11.10 17:55:49.065 DEBUG [CheckContainer] paymentComplete( PaymentEntity{, number=1, dateCreate=Fri Oct 11 17:55:49 MSK 2019, dateCommit=Fri Oct 11 17:55:49 MSK 2019, sumPay=3600, sumPayBaseCurrency=3600, purchase=PurchaseEntity [id=44672, number=null, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=null, fiscalDocNum=null, sentToServerStatus=NO_SENT], paymentType='CashPaymentEntity', baseCurrency='RUB', currency='RUB', successProcessed=true, originalPaymentNumber=null} , 0
11.10 17:55:49.075 INFO  [TechProcessShift] fiscalizeCheck PurchaseEntity [id=44672, number=null, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=null, fiscalDocNum=null, sentToServerStatus=NO_SENT]
11.10 17:55:49.114 TRACE [Runner] Runner begin work ru.crystals.pos.visualization.Factory$21
11.10 17:55:49.114 TRACE [Runner] Runner end work ru.crystals.pos.visualization.Factory$21
11.10 17:55:49.131 DEBUG [KeyboardImpl] -> KEY RELEASED: keyCode = 10
11.10 17:55:49.133 INFO  [FiscalPrinter] getLastKpk
11.10 17:55:49.134 INFO  [FiscalPrinter] LastKpk = 75
11.10 17:55:49.137 WARN  [EgaisExciseValidationImpl] call : sendExciseData()
11.10 17:55:49.177 INFO  [GTDService] GTD purchase process: PurchaseEntity [id=44672, number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=null, fiscalDocNum=null, sentToServerStatus=NO_SENT]
11.10 17:55:49.178 TRACE [HibernateBackedLoyTxDao] entering getLoyTxByReceipt(PurchaseEntity). The argument is: purchase  [PurchaseEntity [id=44672, number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=null, fiscalDocNum=null, sentToServerStatus=NO_SENT]]
11.10 17:55:49.178 TRACE [HibernateBackedLoyTxDao] loy-tx-id of the receipt is not null: 327962
11.10 17:55:49.178 TRACE [HibernateBackedLoyTxDao] entering getLoyTxById(long). The argument is: loyTxId [327962]
11.10 17:55:49.179 TRACE [HibernateBackedLoyTxDao] 1 loy-txes were extracted
11.10 17:55:49.199 TRACE [HibernateBackedLoyTxDao] leaving getLoyTxById(long). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 21 [ms]
11.10 17:55:49.199 TRACE [HibernateBackedLoyTxDao] leaving getLoyTxByReceipt(PurchaseEntity). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 21 [ms]
11.10 17:55:49.200 TRACE [HibernateBackedLoyTxDao] entering getLoyTxByReceipt(PurchaseEntity). The argument is: purchase  [PurchaseEntity [id=44672, number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=null, fiscalDocNum=null, sentToServerStatus=NO_SENT]]
11.10 17:55:49.200 TRACE [HibernateBackedLoyTxDao] loy-tx-id of the receipt is not null: 327962
11.10 17:55:49.200 TRACE [HibernateBackedLoyTxDao] entering getLoyTxById(long). The argument is: loyTxId [327962]
11.10 17:55:49.201 TRACE [HibernateBackedLoyTxDao] 1 loy-txes were extracted
11.10 17:55:49.205 TRACE [HibernateBackedLoyTxDao] leaving getLoyTxById(long). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 5 [ms]
11.10 17:55:49.205 TRACE [HibernateBackedLoyTxDao] leaving getLoyTxByReceipt(PurchaseEntity). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 5 [ms]
11.10 17:55:49.207 TRACE [LoyalServiceImpl] entering beforeFiscalize(PurchaseEntity). The argument is: purchase [PurchaseEntity [id=44672, number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=null, fiscalDocNum=null, sentToServerStatus=NO_SENT]]
11.10 17:55:49.207 TRACE [LoyalServiceImpl] leaving beforeFiscalize(PurchaseEntity). it took 0 [ms]
11.10 17:55:49.207 TRACE [HibernateBackedLoyTxDao] entering getLoyTxByReceipt(PurchaseEntity). The argument is: purchase  [PurchaseEntity [id=44672, number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=null, fiscalDocNum=null, sentToServerStatus=NO_SENT]]
11.10 17:55:49.207 TRACE [HibernateBackedLoyTxDao] loy-tx-id of the receipt is not null: 327962
11.10 17:55:49.207 TRACE [HibernateBackedLoyTxDao] entering getLoyTxById(long). The argument is: loyTxId [327962]
11.10 17:55:49.208 TRACE [HibernateBackedLoyTxDao] 1 loy-txes were extracted
11.10 17:55:49.227 TRACE [HibernateBackedLoyTxDao] leaving getLoyTxById(long). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 20 [ms]
11.10 17:55:49.228 TRACE [HibernateBackedLoyTxDao] leaving getLoyTxByReceipt(PurchaseEntity). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 21 [ms]
11.10 17:55:49.233 INFO  [DocumentTemplate] =====0=====
11.10 17:55:49.233 INFO  [DocumentTemplate] ******************************************"ПАР||NORMAL
11.10 17:55:49.233 INFO  [DocumentTemplate]  АД СКИДОК! Не забудьте 1 купон со скидками у ||NORMAL
11.10 17:55:49.233 INFO  [DocumentTemplate]                    кассира"                   ||NORMAL
11.10 17:55:49.233 INFO  [FiscalPrinter] openMoneyDrawer
11.10 17:55:49.234 INFO  [FiscalPrinter] setCashDrawerOpen(true)
11.10 17:55:49.234 INFO  [TechProcessImpl] Ящик открыт
11.10 17:55:49.234 INFO  [FiscalPrinter] isMoneyDrawerOpen
11.10 17:55:49.258 TRACE [LoyalServiceImpl] entering searchDiscountResultsInDB(Long, boolean). The arguments are: loyTransactionId [327962], useCached [false]
11.10 17:55:49.258 TRACE [HibernateBackedLoyTxDao] entering getLoyTxById(long). The argument is: loyTxId [327962]
11.10 17:55:49.266 TRACE [HibernateBackedLoyTxDao] 1 loy-txes were extracted
11.10 17:55:49.270 TRACE [HibernateBackedLoyTxDao] leaving getLoyTxById(long). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 12 [ms]
11.10 17:55:49.271 TRACE [LoyalServiceImpl] leaving searchDiscountResultsInDB(Long, boolean). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 13 [ms]
11.10 17:55:49.271 TRACE [LoyalServiceImpl] get manual advertising actions guids in purchase..
11.10 17:55:49.271 TRACE [LoyalServiceImpl] number of manual advertising actions guids in purchase = 0
11.10 17:55:49.271 DEBUG [LoyalServiceImpl] getAdvertisingActions.. number of manual actions = 0
11.10 17:55:49.271 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
11.10 17:55:49.271 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:49.271+0300], manualActionGuids: []
11.10 17:55:49.271 TRACE [AdvActionsCacheImpl] leaving getActiveActions(Date, Set). The result is: [AdvertisingActionEntity{id=32427, guid=5661110, parentGuid=5660920, name='[SR-2906] - Печать внутри чека слипов лояльности акции Set10 с результатом "Реклама на чеке" — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3690.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32464, guid=4616066, parentGuid=4615424, name='МСК_УЦ_30%_на_товар_с_подходящим_сроком_годности', mode=AUTOMATIC, worksAnytime=false, useRestrictions=true, priority=3480.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32441, guid=361580, parentGuid=null, name='Лотерея ДР ВКТ  — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3770.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32571, guid=379822, parentGuid=5664429, name='Округление + безнал', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=3780.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32655, guid=5664571, parentGuid=5664487, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32599, guid=379860, parentGuid=379758, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}]; it took 0 [ms]
11.10 17:55:49.272 DEBUG [LoyalServiceImpl] time of get active actions: 1
11.10 17:55:49.272 TRACE [LoyalServiceImpl] get manual advertising actions guids in purchase..
11.10 17:55:49.272 TRACE [LoyalServiceImpl] number of manual advertising actions guids in purchase = 0
11.10 17:55:49.272 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
11.10 17:55:49.272 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:49.272+0300], manualActionGuids: []
11.10 17:55:49.272 TRACE [AdvActionsCacheImpl] leaving getActiveActions(Date, Set). The result is: [AdvertisingActionEntity{id=32427, guid=5661110, parentGuid=5660920, name='[SR-2906] - Печать внутри чека слипов лояльности акции Set10 с результатом "Реклама на чеке" — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3690.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32464, guid=4616066, parentGuid=4615424, name='МСК_УЦ_30%_на_товар_с_подходящим_сроком_годности', mode=AUTOMATIC, worksAnytime=false, useRestrictions=true, priority=3480.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32441, guid=361580, parentGuid=null, name='Лотерея ДР ВКТ  — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3770.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32571, guid=379822, parentGuid=5664429, name='Округление + безнал', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=3780.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32655, guid=5664571, parentGuid=5664487, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32599, guid=379860, parentGuid=379758, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}]; it took 0 [ms]
11.10 17:55:49.285 TRACE [LoyalServiceImpl] entering preparePurchaseFiscalization(PurchaseEntity). The argument is: purchase [PurchaseEntity [id=44672, number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=null, fiscalDocNum=null, sentToServerStatus=NO_SENT]]
11.10 17:55:49.285 TRACE [HibernateBackedLoyTxDao] entering getLoyTxByReceipt(PurchaseEntity). The argument is: purchase  [PurchaseEntity [id=44672, number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=null, fiscalDocNum=null, sentToServerStatus=NO_SENT]]
11.10 17:55:49.285 TRACE [HibernateBackedLoyTxDao] loy-tx-id of the receipt is not null: 327962
11.10 17:55:49.285 TRACE [HibernateBackedLoyTxDao] entering getLoyTxById(long). The argument is: loyTxId [327962]
11.10 17:55:49.286 TRACE [HibernateBackedLoyTxDao] 1 loy-txes were extracted
11.10 17:55:49.293 TRACE [HibernateBackedLoyTxDao] leaving getLoyTxById(long). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 8 [ms]
11.10 17:55:49.294 TRACE [HibernateBackedLoyTxDao] leaving getLoyTxByReceipt(PurchaseEntity). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 9 [ms]
11.10 17:55:49.294 DEBUG [SetApiPluginLoyProvider] No loyalty plugins found.
11.10 17:55:49.295 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@32430607 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:49.295 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@30423295 wrapping SELECT t3.id,t3.module_name,t3.plugin_name,t3.property_key,t3.property_value,t3.transport_level,t3.priority,t3.description,t3.send_status FROM sales_management_properties t3  WHERE module_name=? AND plugin_name IS NULL
11.10 17:55:49.296 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@32430607 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:49.296 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:55:49.296 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:49.296 INFO  [JDBCMapperImpl]
11.10 17:55:49.296 TRACE [LoyalServiceImpl] entering updateLoyTransaction(LoyTransactionEntity). The argument is: loyTransaction [loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]]
11.10 17:55:49.297 TRACE [HibernateBackedLoyTxDao] entering saveLoyTx(LoyTransactionEntity). The argument is: loyTx [loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]]
11.10 17:55:49.315 TRACE [HibernateBackedLoyTxDao] leaving saveLoyTx(LoyTransactionEntity). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 18 [ms]
11.10 17:55:49.315 TRACE [LoyalServiceImpl] leaving updateLoyTransaction(LoyTransactionEntity). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 19 [ms]
11.10 17:55:49.315 TRACE [LoyalServiceImpl] leaving preparePurchaseFiscalization(PurchaseEntity). it took 30 [ms]
11.10 17:55:49.315 INFO  [FiscalPrinter] printCheck
11.10 17:55:49.316 INFO  [FiscalPrinter] getLastKpk
11.10 17:55:49.316 INFO  [FiscalPrinter] LastKpk = 75
11.10 17:55:49.316 INFO  [FiscalPrinter] Fiscal interrupt: null
11.10 17:55:49.316 INFO  [FiscalPrinter] Get document template /mnt/sda1/tce/storage/crystal-cash/modules/fiscalPrinter/templates/check-sale.xml
11.10 17:55:49.316 INFO  [DocumentTemplate] =====logo=====
11.10 17:55:49.317 INFO  [DocumentTemplate] content: null
11.10 17:55:49.319 INFO  [DocumentTemplate] =====header=====
11.10 17:55:49.320 INFO  [DocumentTemplate] =====position=====
11.10 17:55:49.320 INFO  [DocumentTemplate] НАИМЕНОВАНИЕ   |  ЦЕНА* |КОЛ-ВО|СУММА БЕЗ СК|С||SMALL
11.10 17:55:49.320 INFO  [DocumentTemplate] Булочки Бородинские 36.00   1    36.90   36.00||SMALL
11.10 17:55:49.320 INFO  [DocumentTemplate]  в т.ч. НДС 10.00%         СКИДКА= 0.90    РУБ||SMALL
11.10 17:55:49.320 INFO  [DocumentTemplate]  в т.ч. НДС НДС 10%       %                   ||SMALL
11.10 17:55:49.320 INFO  [DocumentTemplate]  в т.ч. НДС 10.0 %         СКИДКА= 0.90    РУБ||SMALL
11.10 17:55:49.320 INFO  [DocumentTemplate] * с учётом всех скидок и НДС                  ||SMALL
11.10 17:55:49.320 INFO  [DocumentTemplate] =====payment=====
11.10 17:55:49.320 INFO  [DocumentTemplate] =====discount=====
11.10 17:55:49.320 INFO  [DocumentTemplate] ВАША СКИДКА СОСТАВИЛА, руб               =0.90||DOUBLEHEIGHT
11.10 17:55:49.329 INFO  [DocumentTemplate] =====includedSlips=====
11.10 17:55:49.329 INFO  [DocumentTemplate]  ||NORMAL
11.10 17:55:49.329 INFO  [DocumentTemplate] ******************************************"ПАР||NORMAL
11.10 17:55:49.329 INFO  [DocumentTemplate]  АД СКИДОК! Не забудьте 1 купон со скидками у ||NORMAL
11.10 17:55:49.329 INFO  [DocumentTemplate]                    кассира"                   ||NORMAL
11.10 17:55:49.329 INFO  [DocumentTemplate]  ||NORMAL
11.10 17:55:49.330 INFO  [DocumentTemplate] =====tax=====
11.10 17:55:49.330 INFO  [DocumentTemplate] =====total=====
11.10 17:55:49.330 INFO  [DocumentTemplate] =====fiscal=====
11.10 17:55:49.330 INFO  [DocumentTemplate] content: null
11.10 17:55:49.330 INFO  [DocumentTemplate] =====footer=====
11.10 17:55:49.330 INFO  [DocumentTemplate] =====cut=====
11.10 17:55:49.330 INFO  [DocumentTemplate] content: null
11.10 17:55:49.330 INFO  [DocumentTemplate] =====bonuses=====
11.10 17:55:49.445 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327626]; fileName: null; status: NO_SENT
11.10 17:55:49.446 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
SET sent_to_server_status = :status, filename = :fileName
WHERE id IN (:ids)
11.10 17:55:49.447 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 2 [ms]
11.10 17:55:49.447 TRACE [TransferManager] setStatus: [1] loy-txes were updated
11.10 17:55:49.447 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175546_437_73011_3.ser
11.10 17:55:49.447 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:55:49.447 INFO  [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
11.10 17:55:49.447 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:55:49.512 INFO  [FiscalPrinter] getLastKpk
11.10 17:55:49.513 INFO  [FiscalPrinter] LastKpk = 76
11.10 17:55:49.513 TRACE [FiscalPrinter] getFiscalCheckData
11.10 17:55:49.519 INFO  [CheckService] fiscalizeCheck: PurchaseEntity [id=44672, number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=Fri Oct 11 17:55:49 MSK 2019, fiscalDocNum=76;117, sentToServerStatus=UNCOMMITED]
11.10 17:55:49.519 TRACE [ExternalProcessingsImpl] entering purchaseFiscalized(PurchaseEntity)
11.10 17:55:49.519 TRACE [ExternalProcessingsImpl] Purchase fiscalized: no implementation of PlastekServices.
11.10 17:55:49.519 TRACE [ExternalProcessingsImpl] Purchase fiscalized: no implementation of externalLoyaltyService.
11.10 17:55:49.535 TRACE [ExternalProcessingsImpl] about to notify ext-loy-providers that the current receipt [PurchaseEntity [id=44672, number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=Fri Oct 11 17:55:49 MSK 2019, fiscalDocNum=76;117, sentToServerStatus=UNCOMMITED]] was fiscalized...
11.10 17:55:49.535 TRACE [LoyalServiceImpl] entering purchaseFiscalized(PurchaseEntity). The argument is: purchase [PurchaseEntity [id=44672, number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=Fri Oct 11 17:55:49 MSK 2019, fiscalDocNum=76;117, sentToServerStatus=UNCOMMITED]]
11.10 17:55:49.535 TRACE [HibernateBackedLoyTxDao] entering getLoyTxByReceipt(PurchaseEntity). The argument is: purchase  [PurchaseEntity [id=44672, number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=Fri Oct 11 17:55:49 MSK 2019, fiscalDocNum=76;117, sentToServerStatus=UNCOMMITED]]
11.10 17:55:49.536 TRACE [HibernateBackedLoyTxDao] loy-tx-id of the receipt is not null: 327962
11.10 17:55:49.536 TRACE [HibernateBackedLoyTxDao] entering getLoyTxById(long). The argument is: loyTxId [327962]
11.10 17:55:49.537 TRACE [HibernateBackedLoyTxDao] 1 loy-txes were extracted
11.10 17:55:49.541 TRACE [HibernateBackedLoyTxDao] leaving getLoyTxById(long). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 5 [ms]
11.10 17:55:49.542 TRACE [HibernateBackedLoyTxDao] leaving getLoyTxByReceipt(PurchaseEntity). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 7 [ms]
11.10 17:55:49.542 DEBUG [SetApiPluginLoyProvider] No loyalty plugins found.
11.10 17:55:49.542 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
11.10 17:55:49.542 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:49.542+0300], manualActionGuids: []
11.10 17:55:49.542 TRACE [AdvActionsCacheImpl] leaving getActiveActions(Date, Set). The result is: [AdvertisingActionEntity{id=32427, guid=5661110, parentGuid=5660920, name='[SR-2906] - Печать внутри чека слипов лояльности акции Set10 с результатом "Реклама на чеке" — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3690.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32464, guid=4616066, parentGuid=4615424, name='МСК_УЦ_30%_на_товар_с_подходящим_сроком_годности', mode=AUTOMATIC, worksAnytime=false, useRestrictions=true, priority=3480.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32441, guid=361580, parentGuid=null, name='Лотерея ДР ВКТ  — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3770.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32571, guid=379822, parentGuid=5664429, name='Округление + безнал', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=3780.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32655, guid=5664571, parentGuid=5664487, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32599, guid=379860, parentGuid=379758, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}]; it took 0 [ms]
11.10 17:55:49.543 TRACE [LoyaltyRestrictionsServiceImpl] createApplyRestrictionsRequest: request = NULL
11.10 17:55:49.543 TRACE [LoyalServiceImpl] get manual advertising actions guids in purchase..
11.10 17:55:49.543 TRACE [LoyalServiceImpl] number of manual advertising actions guids in purchase = 0
11.10 17:55:49.543 DEBUG [LoyalServiceImpl] getAdvertisingActions.. number of manual actions = 0
11.10 17:55:49.543 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
11.10 17:55:49.543 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:49.543+0300], manualActionGuids: []
11.10 17:55:49.543 TRACE [AdvActionsCacheImpl] leaving getActiveActions(Date, Set). The result is: [AdvertisingActionEntity{id=32427, guid=5661110, parentGuid=5660920, name='[SR-2906] - Печать внутри чека слипов лояльности акции Set10 с результатом "Реклама на чеке" — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3690.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32464, guid=4616066, parentGuid=4615424, name='МСК_УЦ_30%_на_товар_с_подходящим_сроком_годности', mode=AUTOMATIC, worksAnytime=false, useRestrictions=true, priority=3480.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32441, guid=361580, parentGuid=null, name='Лотерея ДР ВКТ  — копия *', mode=UNCONDITIONAL, worksAnytime=false, useRestrictions=true, priority=3770.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32571, guid=379822, parentGuid=5664429, name='Округление + безнал', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=3780.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32655, guid=5664571, parentGuid=5664487, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}, AdvertisingActionEntity{id=32599, guid=379860, parentGuid=379758, name='Округление', mode=AUTOMATIC, worksAnytime=true, useRestrictions=true, priority=1240.0, masterActionGuids=[]}]; it took 0 [ms]
11.10 17:55:49.544 DEBUG [LoyalServiceImpl] time of get active actions: 1
11.10 17:55:49.544 TRACE [HibernateBackedLoyTxDao] entering saveLoyTx(LoyTransactionEntity). The argument is: loyTx [loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]]
11.10 17:55:49.554 TRACE [HibernateBackedLoyTxDao] leaving saveLoyTx(LoyTransactionEntity). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 9 [ms]
11.10 17:55:49.554 TRACE [LoyalServiceImpl] leaving purchaseFiscalized(PurchaseEntity). it took 19 [ms]
11.10 17:55:49.554 TRACE [ExternalProcessingsImpl] leaving purchaseFiscalized(PurchaseEntity). It took 35 [ms]
11.10 17:55:49.554 TRACE [HibernateBackedLoyTxDao] entering getLoyTxByReceipt(PurchaseEntity). The argument is: purchase  [PurchaseEntity [id=44672, number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=Fri Oct 11 17:55:49 MSK 2019, fiscalDocNum=76;117, sentToServerStatus=UNCOMMITED]]
11.10 17:55:49.554 TRACE [HibernateBackedLoyTxDao] loy-tx-id of the receipt is not null: 327962
11.10 17:55:49.554 TRACE [HibernateBackedLoyTxDao] entering getLoyTxById(long). The argument is: loyTxId [327962]
11.10 17:55:49.555 TRACE [HibernateBackedLoyTxDao] 1 loy-txes were extracted
11.10 17:55:49.559 TRACE [HibernateBackedLoyTxDao] leaving getLoyTxById(long). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 5 [ms]
11.10 17:55:49.559 TRACE [HibernateBackedLoyTxDao] leaving getLoyTxByReceipt(PurchaseEntity). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 5 [ms]
11.10 17:55:49.559 DEBUG [ProcessingUniqueCouponManager] issueUniqueCouponsBackground() []
11.10 17:55:49.562 INFO  [FiscalPrinter] printDiscountsReport
11.10 17:55:49.562 INFO  [FiscalPrinter] Get document template /mnt/sda1/tce/storage/crystal-cash/modules/fiscalPrinter/templates/discounts-report.xml
11.10 17:55:49.562 INFO  [DocumentTemplate] =====logo=====
11.10 17:55:49.562 INFO  [DocumentTemplate] content: null
11.10 17:55:49.563 INFO  [DocumentTemplate] =====header=====
11.10 17:55:49.563 INFO  [DocumentTemplate]                                               ||NORMAL
11.10 17:55:49.563 INFO  [DocumentTemplate]                                               ||NORMAL
11.10 17:55:49.563 INFO  [DocumentTemplate] ----------------------------------------      ||NORMAL
11.10 17:55:49.563 INFO  [DocumentTemplate] Смена:10                     ЭКЛЗ:769d1811-348||NORMAL
11.10 17:55:49.563 INFO  [DocumentTemplate] Номер кассы:3                 ИНН:  7802781104||NORMAL
11.10 17:55:49.563 INFO  [DocumentTemplate] Кассир:Администратор Кассовый 456             ||NORMAL
11.10 17:55:49.563 INFO  [DocumentTemplate] ----------------------------------------      ||NORMAL
11.10 17:55:49.563 INFO  [DocumentTemplate] ОТЧЕТ ПО СКИДКАМ        48   11-10-2019  17:55||NORMAL
11.10 17:55:49.563 INFO  [DocumentTemplate] ----------------------------------------      ||NORMAL
11.10 17:55:49.563 INFO  [DocumentTemplate] =====groupByGoods=====
11.10 17:55:49.563 INFO  [DocumentTemplate] content: null
11.10 17:55:49.563 INFO  [DocumentTemplate] =====groupByAA=====
11.10 17:55:49.563 INFO  [DocumentTemplate] =====checkDiscounts=====
11.10 17:55:49.563 INFO  [DocumentTemplate] ----------------------------------------      ||NORMAL
11.10 17:55:49.563 INFO  [DocumentTemplate] Скидки на чек       ||NORMAL
11.10 17:55:49.563 INFO  [DocumentTemplate] ----------------------------------------      ||NORMAL
11.10 17:55:49.563 INFO  [DocumentTemplate] Округление                               =0.90||SMALL
11.10 17:55:49.563 INFO  [DocumentTemplate] =====total=====
11.10 17:55:49.563 INFO  [DocumentTemplate] ----------------------------------------      ||NORMAL
11.10 17:55:49.563 INFO  [DocumentTemplate] ИТОГО СКИДКА НА ЧЕК                      =0.90||NORMAL
11.10 17:55:49.563 INFO  [DocumentTemplate] =====fiscal=====
11.10 17:55:49.563 INFO  [DocumentTemplate] content: null
11.10 17:55:49.563 INFO  [DocumentTemplate] =====footer=====
11.10 17:55:49.563 INFO  [DocumentTemplate] Док N:48                    11-10-2019 17:55  ||NORMAL
11.10 17:55:49.563 INFO  [DocumentTemplate] Спасибо за покупку!                           ||NORMAL
11.10 17:55:49.563 INFO  [DocumentTemplate] =====cut=====
11.10 17:55:49.563 INFO  [DocumentTemplate] content: null
11.10 17:55:49.588 TRACE [LoyalServiceImpl] entering confirmDiscount(PurchaseEntity). The argument is: purchase [PurchaseEntity [id=44672, number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=Fri Oct 11 17:55:49 MSK 2019, fiscalDocNum=76;117, sentToServerStatus=UNCOMMITED]]
11.10 17:55:49.590 TRACE [LoyalServiceImpl] entering searchDiscountResultsInDB(Long, boolean). The arguments are: loyTransactionId [327962], useCached [false]
11.10 17:55:49.590 TRACE [HibernateBackedLoyTxDao] entering getLoyTxById(long). The argument is: loyTxId [327962]
11.10 17:55:49.591 TRACE [HibernateBackedLoyTxDao] 1 loy-txes were extracted
11.10 17:55:49.608 TRACE [HibernateBackedLoyTxDao] leaving getLoyTxById(long). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 18 [ms]
11.10 17:55:49.609 TRACE [LoyalServiceImpl] leaving searchDiscountResultsInDB(Long, boolean). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 20 [ms]
11.10 17:55:49.609 TRACE [HibernateBackedLoyTxDao] entering linkTxToReceipt(LoyTransactionEntity, PurchaseEntity). The arguments are: loyTx [loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]], receipt [PurchaseEntity [id=44672, number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=Fri Oct 11 17:55:49 MSK 2019, fiscalDocNum=76;117, sentToServerStatus=UNCOMMITED]]
11.10 17:55:49.612 TRACE [HibernateBackedLoyTxDao] leaving linkTxToReceipt(LoyTransactionEntity, PurchaseEntity). The result is: loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]; it took 3 [ms]
11.10 17:55:49.613 TRACE [SCService] entering isEnabled()
11.10 17:55:49.613 TRACE [SCService] leaving isEnabled(). the result is: true
11.10 17:55:49.613 TRACE [SCService] Entering commitDiscounts (LoyTransactionEntity, PurchaseEntity). The arguments are loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]], PurchaseEntity [id=44672, number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=Fri Oct 11 17:55:49 MSK 2019, fiscalDocNum=76;117, sentToServerStatus=UNCOMMITED]
11.10 17:55:49.613 TRACE [SCService] Stop send Personal Offer
11.10 17:55:49.613 TRACE [SCService] Remove Personal offer feedback
11.10 17:55:49.613 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@551304 wrapping org.postgresql.jdbc.PgConnection@10e1bdf
11.10 17:55:49.613 TRACE [JdbcBackedLoyFeedbackDao] Entering remove(documentNum = 48, shiftNum = 10, cashNum = 3, shopNum = 73011, providerName = smch, feedbackTime = UNTIL_NOT_FISCALIZED).
11.10 17:55:49.614 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@26386708 wrapping DELETE FROM loy_feedback t20 WHERE shop_number=? AND cash_number=? AND shift_number=? AND doc_number=? AND provider_id=? AND feedback_time=?
11.10 17:55:49.614 TRACE [JdbcBackedLoyFeedbackDao] leaving remove(LoyExtProviderFeedback). The result is: {}
11.10 17:55:49.614 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@551304 wrapping org.postgresql.jdbc.PgConnection@10e1bdf
11.10 17:55:49.614 DEBUG [PoolBase] HikariPool-9 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@10e1bdf
11.10 17:55:49.614 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:49.614 INFO  [JDBCMapperImpl]
11.10 17:55:49.614 INFO  [SCReceiptConverter] Entering createFiscalCheque(purchaseEntity, loyTransactionEntity). The arguments are PurchaseEntity [id=44672, number=48, dateCreate=Fri Oct 11 17:55:30 MSK 2019, dateCommit=Fri Oct 11 17:55:49 MSK 2019, fiscalDocNum=76;117, sentToServerStatus=UNCOMMITED] , loy-tx [shop: 73011, cash: 3, inn: 7802781104, shift: 10, purchase-number: (NULL), discount-value: 90, discount-positions: [discount-position [position-order: 1, discount-amount: 90, adv-action: adv-action [guid: 5664571, action-type: DISCOUNT, apply-mode: AUTOMATIC]]]]
11.10 17:55:49.615 TRACE [SCService] Send request <?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<ChequeRequest xmlns="http://smartcheckout.ru/xsd/s10ren.xsd" ChequeType="Fiscal">
    <RequestID>1570805730837</RequestID>
    <Defer>false</Defer>
    <DateTime>2019-10-11T17:55:49.614+03:00</DateTime>
    <POS>3</POS>
    <Number>1570805730837</Number>
    <Summ>36.90</Summ>
    <Discount>2.439</Discount>
    <SummDiscounted>36.00</SummDiscounted>
    <Item>
        <PositionNumber>1</PositionNumber>
        <Article>1300386</Article>
        <ArticleName>Булочки Бородинские 300г п/п</ArticleName>
        <Price>36.90</Price>
        <Quantity>1.000</Quantity>
        <Summ>36.90</Summ>
        <Discount>2.439</Discount>
        <SummDiscounted>36.00</SummDiscounted>
        <ExtendedAttribute>
            <Key>DISCOUNT</Key>
            <Value>2.439</Value>
        </ExtendedAttribute>
    </Item>
</ChequeRequest>

11.10 17:55:49.615 TRACE [SCService] entering getServices()
11.10 17:55:49.615 TRACE [SCService] getting services (IN MEMORY)
11.10 17:55:49.615 TRACE [SCService] leaving getServices(). The result size is: 2
11.10 17:55:49.627 TRACE [SCService] Received response: <?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<ChequeRequestResponce xmlns="http://smartcheckout.ru/xsd/s10ren.xsd">
    <RequestID>1570805730837</RequestID>
    <Processed>2019-10-11T17:55:49.619+03:00</Processed>
    <ReturnCode>0</ReturnCode>
    <CashierMessageTO>0</CashierMessageTO>
    <Summ>36.90</Summ>
    <Discount>2.439</Discount>
    <SummDiscounted>36.00</SummDiscounted>
    <Item>
        <PositionNumber>1</PositionNumber>
        <Article>1300386</Article>
        <ArticleName>Булочки Бородинские 300г п/п</ArticleName>
        <Price>36.90</Price>
        <MinPrice>0</MinPrice>
        <Quantity>1.000</Quantity>
        <Summ>36.90</Summ>
        <Discount>2.439</Discount>
        <SummDiscounted>36.00</SummDiscounted>
        <ExtendedAttribute>
            <Key>DISCOUNT</Key>
            <Value>2.439</Value>
        </ExtendedAttribute>
    </Item>
</ChequeRequestResponce>

11.10 17:55:49.745 INFO  [FiscalPrinter] isMoneyDrawerOpen
11.10 17:55:50.246 INFO  [FiscalPrinter] isMoneyDrawerOpen
11.10 17:55:50.434 DEBUG [HikariPool] HikariPool-5 - Pool stats (total=1, active=0, idle=1, waiting=0)
11.10 17:55:50.746 INFO  [FiscalPrinter] isMoneyDrawerOpen
11.10 17:55:51.247 INFO  [FiscalPrinter] isMoneyDrawerOpen
11.10 17:55:52.492 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327627]; fileName: null; status: NO_SENT
11.10 17:55:52.492 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
SET sent_to_server_status = :status, filename = :fileName
WHERE id IN (:ids)
11.10 17:55:52.494 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 2 [ms]
11.10 17:55:52.494 TRACE [TransferManager] setStatus: [1] loy-txes were updated
11.10 17:55:52.494 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175549_447_73011_3.ser
11.10 17:55:52.494 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:55:52.495 INFO  [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
11.10 17:55:52.495 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:55:53.822 DEBUG [HikariPool] HikariPool-6 - Pool stats (total=5, active=0, idle=5, waiting=0)
11.10 17:55:54.945 DEBUG [HikariPool] HikariPool-7 - Pool stats (total=5, active=0, idle=5, waiting=0)
11.10 17:55:55.223 DEBUG [HikariPool] HikariPool-8 - Pool stats (total=1, active=0, idle=1, waiting=0)
11.10 17:55:55.498 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327628]; fileName: null; status: NO_SENT
11.10 17:55:55.499 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
SET sent_to_server_status = :status, filename = :fileName
WHERE id IN (:ids)
11.10 17:55:55.501 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 3 [ms]
11.10 17:55:55.501 TRACE [TransferManager] setStatus: [1] loy-txes were updated
11.10 17:55:55.501 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175552_495_73011_3.ser
11.10 17:55:55.501 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:55:55.501 INFO  [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
11.10 17:55:55.501 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:55:57.522 DEBUG [TechProcessImpl] Server offline mode
11.10 17:55:57.522 TRACE [Runner] Runner begin work ru.crystals.pos.visualization.Factory$10
11.10 17:55:57.523 TRACE [Runner] Runner end work ru.crystals.pos.visualization.Factory$10
11.10 17:55:58.503 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327629]; fileName: null; status: NO_SENT
11.10 17:55:58.503 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
SET sent_to_server_status = :status, filename = :fileName
WHERE id IN (:ids)
11.10 17:55:58.505 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 2 [ms]
11.10 17:55:58.505 TRACE [TransferManager] setStatus: [1] loy-txes were updated
11.10 17:55:58.505 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175555_501_73011_3.ser
11.10 17:55:58.505 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:55:58.505 INFO  [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
11.10 17:55:58.506 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:55:59.275 DEBUG [SetApiLoyaltyPluginBackgroundWorker] Queue returned null
11.10 17:55:59.276 DEBUG [SetApiLoyaltyPluginBackgroundWorker] Queue has no items, returning to polling.
11.10 17:55:59.276 DEBUG [SetApiLoyaltyPluginBackgroundWorker] Polling...
11.10 17:55:59.276 INFO  [PendingOperationQueue] Pending cards operation queue is empty. Populating from DB...
11.10 17:55:59.286 INFO  [LoyProvidersRegistryImpl] Resend stale feedback
11.10 17:55:59.286 INFO  [LoyProvidersRegistryImpl] looking up LoyFeedbackDao...
11.10 17:55:59.286 INFO  [LoyProvidersRegistryImpl] Search for stale feedback provider = smch
11.10 17:55:59.286 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@16333118 wrapping org.postgresql.jdbc.PgConnection@10e1bdf
11.10 17:55:59.287 TRACE [JdbcBackedLoyFeedbackDao] entering getFeedbackByProviderAndTime(providerId, maxCount). The arguments are smch AS_SOON_AS_POSSIBLE
11.10 17:55:59.287 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@2255873 wrapping SELECT * FROM loy_feedback WHERE provider_id = ? AND feedback_time = ? LIMIT ?
11.10 17:55:59.287 TRACE [JdbcBackedLoyFeedbackDao] leaving getFeedbackByProviderAndTime(smch). The result is: []
11.10 17:55:59.288 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@16333118 wrapping org.postgresql.jdbc.PgConnection@10e1bdf
11.10 17:55:59.288 DEBUG [PoolBase] HikariPool-9 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@10e1bdf
11.10 17:55:59.288 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:59.288 INFO  [JDBCMapperImpl]
11.10 17:55:59.288 INFO  [LoyProvidersRegistryImpl] There is no stale feedback for smch
11.10 17:55:59.288 INFO  [LoyProvidersRegistryImpl] Search for stale feedback provider = SetApiLoyaltyPlugin
11.10 17:55:59.288 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@31422894 wrapping org.postgresql.jdbc.PgConnection@10e1bdf
11.10 17:55:59.288 TRACE [JdbcBackedLoyFeedbackDao] entering getFeedbackByProviderAndTime(providerId, maxCount). The arguments are SetApiLoyaltyPlugin AS_SOON_AS_POSSIBLE
11.10 17:55:59.288 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@285296 wrapping SELECT * FROM loy_feedback WHERE provider_id = ? AND feedback_time = ? LIMIT ?
11.10 17:55:59.289 TRACE [JdbcBackedLoyFeedbackDao] leaving getFeedbackByProviderAndTime(SetApiLoyaltyPlugin). The result is: []
11.10 17:55:59.289 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@31422894 wrapping org.postgresql.jdbc.PgConnection@10e1bdf
11.10 17:55:59.289 DEBUG [PoolBase] HikariPool-9 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@10e1bdf
11.10 17:55:59.289 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:59.289 INFO  [JDBCMapperImpl]
11.10 17:55:59.289 INFO  [LoyProvidersRegistryImpl] There is no stale feedback for SetApiLoyaltyPlugin
11.10 17:55:59.289 INFO  [LoyProvidersRegistryImpl] Search for stale feedback provider = ml
11.10 17:55:59.289 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@299385 wrapping org.postgresql.jdbc.PgConnection@10e1bdf
11.10 17:55:59.289 TRACE [JdbcBackedLoyFeedbackDao] entering getFeedbackByProviderAndTime(providerId, maxCount). The arguments are ml AS_SOON_AS_POSSIBLE
11.10 17:55:59.289 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@12621918 wrapping SELECT * FROM loy_feedback WHERE provider_id = ? AND feedback_time = ? LIMIT ?
11.10 17:55:59.293 TRACE [JdbcBackedLoyFeedbackDao] leaving getFeedbackByProviderAndTime(ml). The result is: [LoyExtProviderFeedback{id=32783, payload=<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<ProcessRequest xmlns="http://loyalty.manzanagroup.ru/loyalty.xsd">
    <request>
        <ChequeRequest>
            <Card>
                <CardNumber>offlinecard1</CardNumber>
            </Card>
            <DateTime>2019-10-11T17:15:04.948+03:00</DateTime>
            <Organization>1</Organization>
            <BusinessUnit>SCO</BusinessUnit>
            <POS>3</POS>
            <Number>1570803304138</Number>
            <OperationType>Return</OperationType>
            <Summ>20.00</Summ>
            <Discount>0.000</Discount>
            <SummDiscounted>20.00</SummDiscounted>
            <Item>
                <PositionNumber>1</PositionNumber>
                <Article>1068918</Article>
                <ArticleName>М/изд Квартал 400г Завитки п/п</ArticleName>
                <Price>20.00</Price>
                <Quantity>1.000</Quantity>
                <Summ>20.00</Summ>
                <Discount>0.000</Discount>
                <SummDiscounted>20.00</SummDiscounted>
            </Item>
        </ChequeRequest>
    </request>
</ProcessRequest>
}, LoyExtProviderFeedback{id=32784, payload=<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<ProcessRequest xmlns="http://loyalty.manzanagroup.ru/loyalty.xsd">
    <request>
        <ChequeRequest>
            <Card>
                <CardNumber>offlinecard1</CardNumber>
            </Card>
            <DateTime>2019-10-11T17:15:22.683+03:00</DateTime>
            <Organization>1</Organization>
            <BusinessUnit>SCO</BusinessUnit>
            <POS>3</POS>
            <Number>1570803321755</Number>
            <OperationType>Return</OperationType>
            <Summ>399.00</Summ>
            <Discount>0.000</Discount>
            <SummDiscounted>399.00</SummDiscounted>
            <Item>
                <PositionNumber>1</PositionNumber>
                <Article>1246672</Article>
                <ArticleName>Десерт Джильдо Рачелли 500г Тирамису</ArticleName>
                <Price>399.00</Price>
                <Quantity>1.000</Quantity>
                <Summ>399.00</Summ>
                <Discount>0.000</Discount>
                <SummDiscounted>399.00</SummDiscounted>
            </Item>
        </ChequeRequest>
    </request>
</ProcessRequest>
}, LoyExtProviderFeedback{id=32791, payload=<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<ProcessRequest xmlns="http://loyalty.manzanagroup.ru/loyalty.xsd">
    <request>
        <ChequeRequest>
            <Card>
                <CardNumber>offlinecard1</CardNumber>
            </Card>
            <DateTime>2019-10-11T17:27:23.802+03:00</DateTime>
            <Organization>1</Organization>
            <BusinessUnit>SCO</BusinessUnit>
            <POS>3</POS>
            <Number>1570804042558</Number>
            <OperationType>Return</OperationType>
            <Summ>39.00</Summ>
            <Discount>0.000</Discount>
            <SummDiscounted>39.00</SummDiscounted>
            <Item>
                <PositionNumber>1</PositionNumber>
                <Article>1266040</Article>
                <ArticleName>Салфетка микрофибра 25*25см Хоум Текстил</ArticleName>
                <Price>39.00</Price>
                <Quantity>1.000</Quantity>
                <Summ>39.00</Summ>
                <Discount>0.000</Discount>
                <SummDiscounted>39.00</SummDiscounted>
            </Item>
        </ChequeRequest>
    </request>
</ProcessRequest>
}, LoyExtProviderFeedback{id=32795, payload=<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<ProcessRequest xmlns="http://loyalty.manzanagroup.ru/loyalty.xsd">
    <request>
        <ChequeRequest>
            <Card>
                <CardNumber>offlinecard1</CardNumber>
            </Card>
            <DateTime>2019-10-11T17:42:34.094+03:00</DateTime>
            <Organization>1</Organization>
            <BusinessUnit>SCO</BusinessUnit>
            <POS>3</POS>
            <Number>1570804951770</Number>
            <OperationType>Return</OperationType>
            <Summ>284.90</Summ>
            <Discount>0.316</Discount>
            <SummDiscounted>284.00</SummDiscounted>
            <Item>
                <PositionNumber>1</PositionNumber>
                <Article>1114576</Article>
                <ArticleName>Чахохбили 4Сезона 600г фасолью</ArticleName>
                <Price>284.90</Price>
                <Quantity>1.000</Quantity>
                <Summ>284.90</Summ>
                <Discount>0.316</Discount>
                <SummDiscounted>284.00</SummDiscounted>
                <ExtendedAttribute>
                    <Key>DISCOUNT</Key>
                    <Value>0.316</Value>
                </ExtendedAttribute>
            </Item>
        </ChequeRequest>
    </request>
</ProcessRequest>
}, LoyExtProviderFeedback{id=32782, payload=<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<ProcessRequest xmlns="http://loyalty.manzanagroup.ru/loyalty.xsd">
    <request>
        <ChequeRequest>
            <Card>
                <CardNumber>offlinecard1</CardNumber>
            </Card>
            <DateTime>2019-10-11T17:13:17.133+03:00</DateTime>
            <Organization>1</Organization>
            <BusinessUnit>SCO</BusinessUnit>
            <POS>3</POS>
            <Number>1570803194586</Number>
            <OperationType>Return</OperationType>
            <Summ>84.90</Summ>
            <Discount>1.060</Discount>
            <SummDiscounted>84.00</SummDiscounted>
            <Item>
                <PositionNumber>1</PositionNumber>
                <Article>1266575</Article>
                <ArticleName>Сметана Простоквашино 315г 25% пл/ст</ArticleName>
                <Price>84.90</Price>
                <Quantity>1.000</Quantity>
                <Summ>84.90</Summ>
                <Discount>1.060</Discount>
                <SummDiscounted>84.00</SummDiscounted>
                <ExtendedAttribute>
                    <Key>DISCOUNT</Key>
                    <Value>1.060</Value>
                </ExtendedAttribute>
            </Item>
        </ChequeRequest>
    </request>
</ProcessRequest>
}]
11.10 17:55:59.294 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@299385 wrapping org.postgresql.jdbc.PgConnection@10e1bdf
11.10 17:55:59.294 DEBUG [PoolBase] HikariPool-9 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@10e1bdf
11.10 17:55:59.294 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:59.294 INFO  [JDBCMapperImpl]
11.10 17:55:59.294 INFO  [LoyProvidersRegistryImpl] Found 5 stale feedback for ml. Submit to executor
11.10 17:55:59.297 INFO  [PendingOperationQueue] No pending card operations found.
11.10 17:55:59.308 INFO  [LoyProvidersRegistryImpl] Search for stale feedback provider = set-loy-provider
11.10 17:55:59.308 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@22398429 wrapping org.postgresql.jdbc.PgConnection@10e1bdf
11.10 17:55:59.308 TRACE [JdbcBackedLoyFeedbackDao] entering getFeedbackByProviderAndTime(providerId, maxCount). The arguments are set-loy-provider AS_SOON_AS_POSSIBLE
11.10 17:55:59.308 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@18519482 wrapping SELECT * FROM loy_feedback WHERE provider_id = ? AND feedback_time = ? LIMIT ?
11.10 17:55:59.309 TRACE [JdbcBackedLoyFeedbackDao] leaving getFeedbackByProviderAndTime(set-loy-provider). The result is: []
11.10 17:55:59.309 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@22398429 wrapping org.postgresql.jdbc.PgConnection@10e1bdf
11.10 17:55:59.309 DEBUG [PoolBase] HikariPool-9 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@10e1bdf
11.10 17:55:59.309 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:55:59.309 INFO  [JDBCMapperImpl]
11.10 17:55:59.309 INFO  [LoyProvidersRegistryImpl] There is no stale feedback for set-loy-provider
11.10 17:55:59.540 DEBUG [HikariPool] HikariPool-9 - Pool stats (total=5, active=0, idle=5, waiting=0)
11.10 17:56:01.522 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327690]; fileName: null; status: NO_SENT
11.10 17:56:01.522 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
SET sent_to_server_status = :status, filename = :fileName
WHERE id IN (:ids)
11.10 17:56:01.523 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 1 [ms]
11.10 17:56:01.523 TRACE [TransferManager] setStatus: [1] loy-txes were updated
11.10 17:56:01.523 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175558_507_73011_3.ser
11.10 17:56:01.524 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:56:01.524 INFO  [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
11.10 17:56:01.524 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:56:04.531 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327691]; fileName: null; status: NO_SENT
11.10 17:56:04.531 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
SET sent_to_server_status = :status, filename = :fileName
WHERE id IN (:ids)
11.10 17:56:04.533 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 2 [ms]
11.10 17:56:04.533 TRACE [TransferManager] setStatus: [1] loy-txes were updated
11.10 17:56:04.533 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175601_524_73011_3.ser
11.10 17:56:04.534 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:56:04.535 INFO  [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
11.10 17:56:04.536 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:56:07.542 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327694]; fileName: null; status: NO_SENT
11.10 17:56:07.542 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
SET sent_to_server_status = :status, filename = :fileName
WHERE id IN (:ids)
11.10 17:56:07.546 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 4 [ms]
11.10 17:56:07.547 TRACE [TransferManager] setStatus: [1] loy-txes were updated
11.10 17:56:07.547 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175604_536_73011_3.ser
11.10 17:56:07.548 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:56:07.548 INFO  [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
11.10 17:56:07.548 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:56:08.321 DEBUG [HikariPool] HikariPool-1 - Pool stats (total=5, active=0, idle=5, waiting=0)
11.10 17:56:10.555 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327740]; fileName: null; status: NO_SENT
11.10 17:56:10.556 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
SET sent_to_server_status = :status, filename = :fileName
WHERE id IN (:ids)
11.10 17:56:10.561 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 6 [ms]
11.10 17:56:10.561 TRACE [TransferManager] setStatus: [1] loy-txes were updated
11.10 17:56:10.561 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175607_548_73011_3.ser
11.10 17:56:10.561 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:56:10.561 INFO  [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
11.10 17:56:10.561 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:56:10.904 DEBUG [HikariPool] HikariPool-2 - Pool stats (total=5, active=0, idle=5, waiting=0)
11.10 17:56:11.217 DEBUG [HikariPool] HikariPool-3 - Pool stats (total=5, active=0, idle=5, waiting=0)
11.10 17:56:11.494 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:56:11.495 INFO  [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
11.10 17:56:11.495 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:56:11.495 ERROR [DocumentSender] Send document error:
java.net.SocketTimeoutException: connect timed out
    at java.net.PlainSocketImpl.socketConnect(Native Method) ~[?:1.8.0_112]
    at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350) ~[?:1.8.0_112]
    at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206) ~[?:1.8.0_112]
    at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188) ~[?:1.8.0_112]
    at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) ~[?:1.8.0_112]
    at java.net.Socket.connect(Socket.java:589) ~[?:1.8.0_112]
    at sun.net.NetworkClient.doConnect(NetworkClient.java:175) ~[?:1.8.0_112]
    at sun.net.www.http.HttpClient.openServer(HttpClient.java:432) ~[?:1.8.0_112]
    at sun.net.www.http.HttpClient.openServer(HttpClient.java:527) ~[?:1.8.0_112]
    at sun.net.www.http.HttpClient.<init>(HttpClient.java:211) ~[?:1.8.0_112]
    at sun.net.www.http.HttpClient.New(HttpClient.java:308) ~[?:1.8.0_112]
    at sun.net.www.http.HttpClient.New(HttpClient.java:326) ~[?:1.8.0_112]
    at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1202) ~[?:1.8.0_112]
    at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1138) ~[?:1.8.0_112]
    at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1032) ~[?:1.8.0_112]
    at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:966) ~[?:1.8.0_112]
    at ru.crystals.httpclient.HttpFileTransport.getServerOutputFullAddress(HttpFileTransport.java:51) ~[ServerHttpClient.jar:?]
    at ru.crystals.httpclient.HttpFileTransport.getServerOutput(HttpFileTransport.java:40) ~[ServerHttpClient.jar:?]
    at ru.crystals.pos.transport.ModuleConnection.getHttpFileOutputConnection(ModuleConnection.java:65) ~[registry.jar:10.2.74.0]
    at ru.crystals.pos.check.service.transport.DocumentSender.setDocumentToSet10(DocumentSender.java:377) [document.jar:10.2.74.0]
    at ru.crystals.pos.check.service.transport.DocumentSender.sendObject(DocumentSender.java:312) [document.jar:10.2.74.0]
    at ru.crystals.pos.check.service.transport.DocumentSender.exportDocuments(DocumentSender.java:194) [document.jar:10.2.74.0]
    at ru.crystals.pos.check.service.transport.DocumentSender.run(DocumentSender.java:103) [document.jar:10.2.74.0]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_112]
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_112]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_112]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_112]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_112]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_112]
    at java.lang.Thread.run(Thread.java:745) [?:1.8.0_112]
11.10 17:56:11.497 INFO  [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@31517727 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:56:11.497 INFO  [JDBCMapperImpl] Final close connection HikariProxyConnection@31517727 wrapping org.postgresql.jdbc.PgConnection@1c28101
11.10 17:56:11.498 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11.10 17:56:11.498 INFO  [JDBCMapperImpl] Commit transaction:
11.10 17:56:11.498 INFO  [JDBCMapperImpl]
11.10 17:56:13.566 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327760]; fileName: null; status: NO_SENT
11.10 17:56:13.566 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
SET sent_to_server_status = :status, filename = :fileName
WHERE id IN (:ids)
11.10 17:56:13.569 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 3 [ms]
11.10 17:56:13.569 TRACE [TransferManager] setStatus: [1] loy-txes were updated
11.10 17:56:13.569 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175610_561_73011_3.ser
11.10 17:56:13.570 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:56:13.570 INFO  [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
11.10 17:56:13.570 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:56:16.575 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327761]; fileName: null; status: NO_SENT
11.10 17:56:16.575 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
SET sent_to_server_status = :status, filename = :fileName
WHERE id IN (:ids)
11.10 17:56:16.576 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 1 [ms]
11.10 17:56:16.576 TRACE [TransferManager] setStatus: [1] loy-txes were updated
11.10 17:56:16.576 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175613_570_73011_3.ser
11.10 17:56:16.577 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:56:16.577 INFO  [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
11.10 17:56:16.577 INFO  [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
11.10 17:56:16.934 DEBUG [HikariPool] HikariPool-4 - Pool stats (total=5, active=0, idle=5, waiting=0)
^C