· 6 years ago · Oct 11, 2019, 03:04 PM
111.10 17:55:41.486 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@5276338 wrapping org.postgresql.jdbc.PgConnection@1c28101
211.10 17:55:41.486 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@5276338 wrapping org.postgresql.jdbc.PgConnection@1c28101
311.10 17:55:41.486 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
411.10 17:55:41.486 INFO [JDBCMapperImpl] Commit transaction:
511.10 17:55:41.486 INFO [JDBCMapperImpl]
611.10 17:55:41.488 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@27537853 wrapping org.postgresql.jdbc.PgConnection@1c28101
711.10 17:55:41.488 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@27537853 wrapping org.postgresql.jdbc.PgConnection@1c28101
811.10 17:55:41.488 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
911.10 17:55:41.488 INFO [JDBCMapperImpl] Commit transaction:
1011.10 17:55:41.488 INFO [JDBCMapperImpl]
1111.10 17:55:43.419 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327624]; fileName: null; status: NO_SENT
1211.10 17:55:43.419 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
13SET sent_to_server_status = :status, filename = :fileName
14WHERE id IN (:ids)
1511.10 17:55:43.421 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 2 [ms]
1611.10 17:55:43.421 TRACE [TransferManager] setStatus: [1] loy-txes were updated
1711.10 17:55:43.421 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175540_408_73011_3.ser
1811.10 17:55:43.422 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
1911.10 17:55:43.422 INFO [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
2011.10 17:55:43.422 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
2111.10 17:55:44.642 DEBUG [KeyboardImpl] -> KEY PRESSED: keyCode = 107
2211.10 17:55:44.643 DEBUG [KeyboardImpl] -> KEY TYPED: keyCode = 107, keyChar +
2311.10 17:55:44.643 DEBUG [KeyboardImpl] ---> KEY TYPED 2_1: keyCode = 43
2411.10 17:55:44.663 DEBUG [KeyboardImpl] keyboard - keysqueue [[Key scanCode=43]]
2511.10 17:55:44.712 DEBUG [KeyboardImpl] -> KEY RELEASED: keyCode = 107
2611.10 17:55:45.337 DEBUG [KeyboardImpl] -> KEY PRESSED: keyCode = 32
2711.10 17:55:45.337 DEBUG [KeyboardImpl] -> KEY TYPED: keyCode = 32, keyChar
2811.10 17:55:45.337 DEBUG [KeyboardImpl] ---> KEY TYPED 3: keyCode = 32
2911.10 17:55:45.360 DEBUG [KeyboardImpl] keyboard - keysqueue [[Key scanCode=32]]
3011.10 17:55:45.361 INFO [TechProcessImpl] eventFunctionKey: FunctionKey [scanCode=32, command=kbdSubtotal]
3111.10 17:55:45.365 DEBUG [CheckContainer] CheckContainer.subtotal() - Check state: SEARCH_PRODUCT, State purchase: WAIT_GOODS
3211.10 17:55:45.370 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@18246526 wrapping org.postgresql.jdbc.PgConnection@1c28101
3311.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=?
3411.10 17:55:45.370 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@18246526 wrapping org.postgresql.jdbc.PgConnection@1c28101
3511.10 17:55:45.370 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
3611.10 17:55:45.370 INFO [JDBCMapperImpl] Commit transaction:
3711.10 17:55:45.370 INFO [JDBCMapperImpl]
3811.10 17:55:45.370 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@11847117 wrapping org.postgresql.jdbc.PgConnection@1c28101
3911.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=?
4011.10 17:55:45.371 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@11847117 wrapping org.postgresql.jdbc.PgConnection@1c28101
4111.10 17:55:45.371 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
4211.10 17:55:45.371 INFO [JDBCMapperImpl] Commit transaction:
4311.10 17:55:45.371 INFO [JDBCMapperImpl]
4411.10 17:55:45.371 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@2483493 wrapping org.postgresql.jdbc.PgConnection@1c28101
4511.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=?
4611.10 17:55:45.371 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@2483493 wrapping org.postgresql.jdbc.PgConnection@1c28101
4711.10 17:55:45.372 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
4811.10 17:55:45.372 INFO [JDBCMapperImpl] Commit transaction:
4911.10 17:55:45.372 INFO [JDBCMapperImpl]
5011.10 17:55:45.372 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@12921527 wrapping org.postgresql.jdbc.PgConnection@1c28101
5111.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=?
5211.10 17:55:45.372 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@12921527 wrapping org.postgresql.jdbc.PgConnection@1c28101
5311.10 17:55:45.372 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
5411.10 17:55:45.373 INFO [JDBCMapperImpl] Commit transaction:
5511.10 17:55:45.373 INFO [JDBCMapperImpl]
5611.10 17:55:45.373 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@4428901 wrapping org.postgresql.jdbc.PgConnection@1c28101
5711.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=?
5811.10 17:55:45.373 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@4428901 wrapping org.postgresql.jdbc.PgConnection@1c28101
5911.10 17:55:45.373 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
6011.10 17:55:45.373 INFO [JDBCMapperImpl] Commit transaction:
6111.10 17:55:45.373 INFO [JDBCMapperImpl]
6211.10 17:55:45.374 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@17536263 wrapping org.postgresql.jdbc.PgConnection@1c28101
6311.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=?
6411.10 17:55:45.374 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@17536263 wrapping org.postgresql.jdbc.PgConnection@1c28101
6511.10 17:55:45.374 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
6611.10 17:55:45.376 DEBUG [KeyboardImpl] -> KEY RELEASED: keyCode = 32
6711.10 17:55:45.376 INFO [JDBCMapperImpl] Commit transaction:
6811.10 17:55:45.376 INFO [JDBCMapperImpl]
6911.10 17:55:45.376 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@11740439 wrapping org.postgresql.jdbc.PgConnection@1c28101
7011.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=?
7111.10 17:55:45.376 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@11740439 wrapping org.postgresql.jdbc.PgConnection@1c28101
7211.10 17:55:45.376 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
7311.10 17:55:45.376 INFO [JDBCMapperImpl] Commit transaction:
7411.10 17:55:45.376 INFO [JDBCMapperImpl]
7511.10 17:55:45.377 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@18368257 wrapping org.postgresql.jdbc.PgConnection@1c28101
7611.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=?
7711.10 17:55:45.377 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@18368257 wrapping org.postgresql.jdbc.PgConnection@1c28101
7811.10 17:55:45.377 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
7911.10 17:55:45.377 INFO [JDBCMapperImpl] Commit transaction:
8011.10 17:55:45.377 INFO [JDBCMapperImpl]
8111.10 17:55:45.377 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@25588845 wrapping org.postgresql.jdbc.PgConnection@1c28101
8211.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=?
8311.10 17:55:45.378 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@25588845 wrapping org.postgresql.jdbc.PgConnection@1c28101
8411.10 17:55:45.378 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
8511.10 17:55:45.378 INFO [JDBCMapperImpl] Commit transaction:
8611.10 17:55:45.378 INFO [JDBCMapperImpl]
8711.10 17:55:45.378 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@5430624 wrapping org.postgresql.jdbc.PgConnection@1c28101
8811.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=?
8911.10 17:55:45.378 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@5430624 wrapping org.postgresql.jdbc.PgConnection@1c28101
9011.10 17:55:45.378 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
9111.10 17:55:45.378 INFO [JDBCMapperImpl] Commit transaction:
9211.10 17:55:45.378 INFO [JDBCMapperImpl]
9311.10 17:55:45.378 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@22002622 wrapping org.postgresql.jdbc.PgConnection@1c28101
9411.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=?
9511.10 17:55:45.378 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@22002622 wrapping org.postgresql.jdbc.PgConnection@1c28101
9611.10 17:55:45.378 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
9711.10 17:55:45.379 INFO [JDBCMapperImpl] Commit transaction:
9811.10 17:55:45.379 INFO [JDBCMapperImpl]
9911.10 17:55:45.379 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@18981753 wrapping org.postgresql.jdbc.PgConnection@1c28101
10011.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=?
10111.10 17:55:45.379 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@18981753 wrapping org.postgresql.jdbc.PgConnection@1c28101
10211.10 17:55:45.379 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
10311.10 17:55:45.379 INFO [JDBCMapperImpl] Commit transaction:
10411.10 17:55:45.379 INFO [JDBCMapperImpl]
10511.10 17:55:45.379 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@7956866 wrapping org.postgresql.jdbc.PgConnection@1c28101
10611.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=?
10711.10 17:55:45.379 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@7956866 wrapping org.postgresql.jdbc.PgConnection@1c28101
10811.10 17:55:45.380 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
10911.10 17:55:45.380 INFO [JDBCMapperImpl] Commit transaction:
11011.10 17:55:45.380 INFO [JDBCMapperImpl]
11111.10 17:55:45.380 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@33513478 wrapping org.postgresql.jdbc.PgConnection@1c28101
11211.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=?
11311.10 17:55:45.380 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@33513478 wrapping org.postgresql.jdbc.PgConnection@1c28101
11411.10 17:55:45.380 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
11511.10 17:55:45.381 INFO [JDBCMapperImpl] Commit transaction:
11611.10 17:55:45.381 INFO [JDBCMapperImpl]
11711.10 17:55:45.381 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@32904577 wrapping org.postgresql.jdbc.PgConnection@1c28101
11811.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=?
11911.10 17:55:45.381 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@32904577 wrapping org.postgresql.jdbc.PgConnection@1c28101
12011.10 17:55:45.381 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
12111.10 17:55:45.382 INFO [JDBCMapperImpl] Commit transaction:
12211.10 17:55:45.382 INFO [JDBCMapperImpl]
12311.10 17:55:45.382 DEBUG [SetApiGoodsPluginPaymentTypeLimiter] The purchase has no Set API goods
12411.10 17:55:45.384 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@10308877 wrapping org.postgresql.jdbc.PgConnection@1c28101
12511.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=?
12611.10 17:55:45.384 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@10308877 wrapping org.postgresql.jdbc.PgConnection@1c28101
12711.10 17:55:45.384 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
12811.10 17:55:45.384 INFO [JDBCMapperImpl] Commit transaction:
12911.10 17:55:45.384 INFO [JDBCMapperImpl]
13011.10 17:55:45.384 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@26255615 wrapping org.postgresql.jdbc.PgConnection@1c28101
13111.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=?
13211.10 17:55:45.385 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@26255615 wrapping org.postgresql.jdbc.PgConnection@1c28101
13311.10 17:55:45.385 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
13411.10 17:55:45.385 INFO [JDBCMapperImpl] Commit transaction:
13511.10 17:55:45.385 INFO [JDBCMapperImpl]
13611.10 17:55:45.385 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@9385372 wrapping org.postgresql.jdbc.PgConnection@1c28101
13711.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=?
13811.10 17:55:45.385 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@9385372 wrapping org.postgresql.jdbc.PgConnection@1c28101
13911.10 17:55:45.385 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
14011.10 17:55:45.385 INFO [JDBCMapperImpl] Commit transaction:
14111.10 17:55:45.385 INFO [JDBCMapperImpl]
14211.10 17:55:45.385 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@3955701 wrapping org.postgresql.jdbc.PgConnection@1c28101
14311.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=?
14411.10 17:55:45.385 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@3955701 wrapping org.postgresql.jdbc.PgConnection@1c28101
14511.10 17:55:45.385 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
14611.10 17:55:45.386 INFO [JDBCMapperImpl] Commit transaction:
14711.10 17:55:45.386 INFO [JDBCMapperImpl]
14811.10 17:55:45.386 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@2685739 wrapping org.postgresql.jdbc.PgConnection@1c28101
14911.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=?
15011.10 17:55:45.386 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@2685739 wrapping org.postgresql.jdbc.PgConnection@1c28101
15111.10 17:55:45.386 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
15211.10 17:55:45.386 INFO [JDBCMapperImpl] Commit transaction:
15311.10 17:55:45.386 INFO [JDBCMapperImpl]
15411.10 17:55:45.386 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@686954 wrapping org.postgresql.jdbc.PgConnection@1c28101
15511.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=?
15611.10 17:55:45.386 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@686954 wrapping org.postgresql.jdbc.PgConnection@1c28101
15711.10 17:55:45.386 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
15811.10 17:55:45.387 INFO [JDBCMapperImpl] Commit transaction:
15911.10 17:55:45.387 INFO [JDBCMapperImpl]
16011.10 17:55:45.387 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@4933682 wrapping org.postgresql.jdbc.PgConnection@1c28101
16111.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=?
16211.10 17:55:45.387 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@4933682 wrapping org.postgresql.jdbc.PgConnection@1c28101
16311.10 17:55:45.387 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
16411.10 17:55:45.387 INFO [JDBCMapperImpl] Commit transaction:
16511.10 17:55:45.387 INFO [JDBCMapperImpl]
16611.10 17:55:45.387 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@4482664 wrapping org.postgresql.jdbc.PgConnection@1c28101
16711.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=?
16811.10 17:55:45.387 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@4482664 wrapping org.postgresql.jdbc.PgConnection@1c28101
16911.10 17:55:45.387 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
17011.10 17:55:45.387 INFO [JDBCMapperImpl] Commit transaction:
17111.10 17:55:45.387 INFO [JDBCMapperImpl]
17211.10 17:55:45.387 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@27022516 wrapping org.postgresql.jdbc.PgConnection@1c28101
17311.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=?
17411.10 17:55:45.387 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@27022516 wrapping org.postgresql.jdbc.PgConnection@1c28101
17511.10 17:55:45.388 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
17611.10 17:55:45.388 INFO [JDBCMapperImpl] Commit transaction:
17711.10 17:55:45.388 INFO [JDBCMapperImpl]
17811.10 17:55:45.388 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@32571706 wrapping org.postgresql.jdbc.PgConnection@1c28101
17911.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=?
18011.10 17:55:45.388 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@32571706 wrapping org.postgresql.jdbc.PgConnection@1c28101
18111.10 17:55:45.388 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
18211.10 17:55:45.388 INFO [JDBCMapperImpl] Commit transaction:
18311.10 17:55:45.388 INFO [JDBCMapperImpl]
18411.10 17:55:45.388 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@20931850 wrapping org.postgresql.jdbc.PgConnection@1c28101
18511.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=?
18611.10 17:55:45.388 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@20931850 wrapping org.postgresql.jdbc.PgConnection@1c28101
18711.10 17:55:45.388 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
18811.10 17:55:45.388 INFO [JDBCMapperImpl] Commit transaction:
18911.10 17:55:45.388 INFO [JDBCMapperImpl]
19011.10 17:55:45.388 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@8702860 wrapping org.postgresql.jdbc.PgConnection@1c28101
19111.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=?
19211.10 17:55:45.389 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@8702860 wrapping org.postgresql.jdbc.PgConnection@1c28101
19311.10 17:55:45.389 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
19411.10 17:55:45.389 INFO [JDBCMapperImpl] Commit transaction:
19511.10 17:55:45.389 INFO [JDBCMapperImpl]
19611.10 17:55:45.389 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@27602912 wrapping org.postgresql.jdbc.PgConnection@1c28101
19711.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=?
19811.10 17:55:45.389 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@27602912 wrapping org.postgresql.jdbc.PgConnection@1c28101
19911.10 17:55:45.389 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
20011.10 17:55:45.390 INFO [JDBCMapperImpl] Commit transaction:
20111.10 17:55:45.390 INFO [JDBCMapperImpl]
20211.10 17:55:45.390 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@30041255 wrapping org.postgresql.jdbc.PgConnection@1c28101
20311.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=?
20411.10 17:55:45.390 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@30041255 wrapping org.postgresql.jdbc.PgConnection@1c28101
20511.10 17:55:45.390 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
20611.10 17:55:45.390 INFO [JDBCMapperImpl] Commit transaction:
20711.10 17:55:45.390 INFO [JDBCMapperImpl]
20811.10 17:55:45.390 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@7356205 wrapping org.postgresql.jdbc.PgConnection@1c28101
20911.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=?
21011.10 17:55:45.390 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@7356205 wrapping org.postgresql.jdbc.PgConnection@1c28101
21111.10 17:55:45.390 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
21211.10 17:55:45.390 INFO [JDBCMapperImpl] Commit transaction:
21311.10 17:55:45.390 INFO [JDBCMapperImpl]
21411.10 17:55:45.390 DEBUG [SetApiGoodsPluginPaymentTypeLimiter] The purchase has no Set API goods
21511.10 17:55:45.391 TRACE [CheckContainer] subtotalProcessPurchaseState: receipt state is: WAIT_GOODS
21611.10 17:55:45.391 TRACE [CheckContainer] starting subtotal scenario...
21711.10 17:55:45.391 INFO [CommonLogger] busy = true
21811.10 17:55:45.392 TRACE [TechProcessImpl] Start warn divide alco
21911.10 17:55:45.392 TRACE [TechProcessImpl] End warn devide alco
22011.10 17:55:45.396 INFO [TechProcessImpl] goToDiscounts
22111.10 17:55:45.423 INFO [LoyalBridgeServiceImpl] --------------- begin discount calculation ---------------
22211.10 17:55:45.423 TRACE [LoyalServiceImpl] entering doDiscount(PurchaseEntity)
22311.10 17:55:45.423 TRACE [LoyalServiceImpl] entering doLoyalty(PurchaseEntity)
22411.10 17:55:45.423 TRACE [CheckService] entering getExpectedDocNum()
22511.10 17:55:45.423 TRACE [CheckService] the number of the last fiscalized document during the current shift is: 47
22611.10 17:55:45.423 TRACE [CheckService] leaving getExpectedDocNum(). the result is: 48
22711.10 17:55:45.428 INFO [LoyalProductsConverter] Time searching loyal goods for 1 productItems = 5 ms
22811.10 17:55:45.428 INFO [LoyalCalculatorConverter] Time converting 1 positions = 0 ms
22911.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}
23011.10 17:55:45.428 TRACE [MLServiceImpl] leaving getMlCardNo(Purchase). The receipt does not have cards applied
23111.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}
23211.10 17:55:45.428 TRACE [MLServiceImpl] leaving getMlCouponNo(PurchaseEntity). The receipt does not have cards applied
23311.10 17:55:45.429 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
23411.10 17:55:45.429 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.429+0300], manualActionGuids: []
23511.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]
23611.10 17:55:45.430 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
23711.10 17:55:45.431 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.430+0300], manualActionGuids: []
23811.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]
23911.10 17:55:45.432 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
24011.10 17:55:45.432 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.432+0300], manualActionGuids: []
24111.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]
24211.10 17:55:45.432 TRACE [LoyaltyRestrictionsServiceImpl] checkRestrictions: no client, internal card info: 'Not card'
24311.10 17:55:45.432 INFO [DoProcessing] ============ LoyalCalculation: doDiscount start ============
24411.10 17:55:45.432 INFO [DoProcessing] GeneralInteractionMethod: MAXIMUM_DISCOUNT
24511.10 17:55:45.433 INFO [DoProcessing] ============ LoyalCalculation: doDiscount success ============
24611.10 17:55:45.434 TRACE [SCService] entering isEnabled()
24711.10 17:55:45.434 TRACE [SCService] leaving isEnabled(). the result is: true
24811.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}
24911.10 17:55:45.435 TRACE [SCService] Send request <?xml version="1.0" encoding="UTF-8" standalone="yes"?>
250<ChequeRequest xmlns="http://smartcheckout.ru/xsd/s10ren.xsd" ChequeType="Soft">
251 <RequestID>1570805730837</RequestID>
252 <DateTime>2019-10-11T17:55:45.435+03:00</DateTime>
253 <POS>3</POS>
254 <Number>1570805730837</Number>
255 <Summ>36.90</Summ>
256 <Discount>0.000</Discount>
257 <SummDiscounted>36.90</SummDiscounted>
258 <Item>
259 <PositionNumber>1</PositionNumber>
260 <Article>1300386</Article>
261 <ArticleName>Булочки Бородинские 300г п/п</ArticleName>
262 <Price>36.90</Price>
263 <Quantity>1.000</Quantity>
264 <Summ>36.90</Summ>
265 <Discount>0.000</Discount>
266 <SummDiscounted>36.90</SummDiscounted>
267 </Item>
268</ChequeRequest>
269
27011.10 17:55:45.435 TRACE [SCService] entering getServices()
27111.10 17:55:45.435 TRACE [SCService] getting services (IN MEMORY)
27211.10 17:55:45.435 TRACE [SCService] leaving getServices(). The result size is: 2
27311.10 17:55:45.463 TRACE [SCService] Received response: <?xml version="1.0" encoding="UTF-8" standalone="yes"?>
274<ChequeRequestResponce xmlns="http://smartcheckout.ru/xsd/s10ren.xsd">
275 <RequestID>1570805730837</RequestID>
276 <Processed>2019-10-11T17:55:45.438+03:00</Processed>
277 <ReturnCode>0</ReturnCode>
278 <CashierMessageTO>0</CashierMessageTO>
279 <Summ>36.90</Summ>
280 <Discount>0.000</Discount>
281 <SummDiscounted>36.90</SummDiscounted>
282 <Item>
283 <PositionNumber>1</PositionNumber>
284 <Article>1300386</Article>
285 <ArticleName>Булочки Бородинские 300г п/п</ArticleName>
286 <Price>36.90</Price>
287 <MinPrice>0</MinPrice>
288 <Quantity>1.000</Quantity>
289 <Summ>36.90</Summ>
290 <Discount>0.000</Discount>
291 <SummDiscounted>36.90</SummDiscounted>
292 </Item>
293</ChequeRequestResponce>
294
29511.10 17:55:45.464 TRACE [SCReceiptConverter] ml discounts: {position-key [marking: 1300386; original-price: 3690]=0}
29611.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
29711.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]
29811.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}
29911.10 17:55:45.464 TRACE [MLServiceImpl] leaving getMlCardNo(Purchase). The receipt does not have cards applied
30011.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}
30111.10 17:55:45.464 TRACE [MLServiceImpl] leaving getMlCouponNo(PurchaseEntity). The receipt does not have cards applied
30211.10 17:55:45.466 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
30311.10 17:55:45.466 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.466+0300], manualActionGuids: []
30411.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]
30511.10 17:55:45.466 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
30611.10 17:55:45.466 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.466+0300], manualActionGuids: []
30711.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]
30811.10 17:55:45.467 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
30911.10 17:55:45.467 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.467+0300], manualActionGuids: []
31011.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]
31111.10 17:55:45.468 INFO [DoProcessing] ============ LoyalCalculation: doDiscount start ============
31211.10 17:55:45.468 INFO [DoProcessing] GeneralInteractionMethod: MAXIMUM_DISCOUNT
31311.10 17:55:45.468 INFO [DoProcessing] ============ LoyalCalculation: doDiscount success ============
31411.10 17:55:45.468 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
31511.10 17:55:45.468 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.468+0300], manualActionGuids: []
31611.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]
31711.10 17:55:45.468 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
31811.10 17:55:45.468 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.468+0300], manualActionGuids: []
31911.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]
32011.10 17:55:45.469 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
32111.10 17:55:45.469 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.469+0300], manualActionGuids: []
32211.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]
32311.10 17:55:45.469 TRACE [LoyaltyRestrictionsServiceImpl] checkRestrictions: no client, internal card info: 'Not card'
32411.10 17:55:45.469 INFO [DoProcessing] ============ LoyalCalculation: doDiscount start ============
32511.10 17:55:45.469 INFO [DoProcessing] GeneralInteractionMethod: MAXIMUM_DISCOUNT
32611.10 17:55:45.488 INFO [DoProcessing] ============ LoyalCalculation: doDiscount success ============
32711.10 17:55:45.488 DEBUG [SetApiPluginLoyProvider] No suitable Loyalty plugins found
32811.10 17:55:45.488 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
32911.10 17:55:45.488 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.488+0300], manualActionGuids: []
33011.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]
33111.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}
33211.10 17:55:45.489 TRACE [MLServiceImpl] leaving getMlCardNo(Purchase). The receipt does not have cards applied
33311.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}
33411.10 17:55:45.489 TRACE [MLServiceImpl] leaving getMlCouponNo(PurchaseEntity). The receipt does not have cards applied
33511.10 17:55:45.489 DEBUG [DiscountCalculationListener] No suitable Loyalty plugins found to inform them about finishing discount calculation
33611.10 17:55:45.489 INFO [LoyalServiceImpl] Discount calculation (Purchase #48; Positions: 1
33711.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}
33811.10 17:55:45.489 DEBUG [LoyalServiceImpl] getAdvertisingActions.. number of manual actions = 0
33911.10 17:55:45.489 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
34011.10 17:55:45.489 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.489+0300], manualActionGuids: []
34111.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]
34211.10 17:55:45.489 DEBUG [LoyalServiceImpl] time of get active actions: 0
34311.10 17:55:45.535 TRACE [LoyalServiceImpl] leaving doLoyalty(PurchaseEntity)
34411.10 17:55:45.543 TRACE [LoyalServiceImpl] get manual advertising actions guids in purchase..
34511.10 17:55:45.543 TRACE [LoyalServiceImpl] number of manual advertising actions guids in purchase = 0
34611.10 17:55:45.543 DEBUG [LoyalServiceImpl] getAdvertisingActions.. number of manual actions = 0
34711.10 17:55:45.543 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
34811.10 17:55:45.543 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:45.543+0300], manualActionGuids: []
34911.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]
35011.10 17:55:45.543 DEBUG [LoyalServiceImpl] time of get active actions: 0
35111.10 17:55:45.543 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@3649288 wrapping org.postgresql.jdbc.PgConnection@1c28101
35211.10 17:55:45.543 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@3649288 wrapping org.postgresql.jdbc.PgConnection@1c28101
35311.10 17:55:45.543 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
35411.10 17:55:45.543 INFO [JDBCMapperImpl] Commit transaction:
35511.10 17:55:45.543 INFO [JDBCMapperImpl]
35611.10 17:55:45.544 TRACE [LoyalServiceImpl] entering extractNonDiscountRelatedFields(Long). The argument is: null
35711.10 17:55:45.544 WARN [LoyalServiceImpl] extractNonDiscountRelatedFields: the argument is NULL! Null will be returned!
35811.10 17:55:45.544 TRACE [LoyalServiceImpl] leaving extractNonDiscountRelatedFields(Long). The result is: null; it took 0 [ms]
35911.10 17:55:45.544 TRACE [LoyalServiceImpl] entering deleteLoyTransaction(Long). The argument is: null
36011.10 17:55:45.544 TRACE [LoyalServiceImpl] leaving deleteLoyTransaction(Long). The result is: false
36111.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
36211.10 17:55:45.545 TRACE [LoyalServiceImpl] leaving checkCouponsCountAndDeleteExcess(Purchase, int). maxCountOfGeneratedCouponsInCheck = 0 therefore we have no restriction
36311.10 17:55:45.545 TRACE [LoyalCashConverter] Булочки Бородинские 300г п/п - 2 %
36411.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]]]]]
36511.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]]]]]
36611.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]
36711.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]
36811.10 17:55:45.579 INFO [LoyalServiceImpl] Save processed purchase and discounts (Purchase #48; Number of positions: 1). Time: 34 ms.
36911.10 17:55:45.579 TRACE [LoyalServiceImpl] leaving doDiscount(PurchaseEntity)
37011.10 17:55:45.579 INFO [LoyalBridgeServiceImpl] Total time of discount calculation = 156 ms
37111.10 17:55:45.579 INFO [LoyalBridgeServiceImpl] ---------------- end discount calculation ----------------
37211.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]
37311.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
37411.10 17:55:45.595 INFO [CommonLogger] value = 90
37511.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]]
37611.10 17:55:45.599 TRACE [HibernateBackedLoyTxDao] loy-tx-id of the receipt is not null: 327962
37711.10 17:55:45.599 TRACE [HibernateBackedLoyTxDao] entering getLoyTxById(long). The argument is: loyTxId [327962]
37811.10 17:55:45.601 TRACE [HibernateBackedLoyTxDao] 1 loy-txes were extracted
37911.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]
38011.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]
38111.10 17:55:45.608 TRACE [TechProcessImpl] Start warn divide amount
38211.10 17:55:45.608 INFO [TechProcessImpl] goToPayments
38311.10 17:55:45.614 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@8942119 wrapping org.postgresql.jdbc.PgConnection@1c28101
38411.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=?
38511.10 17:55:45.614 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@8942119 wrapping org.postgresql.jdbc.PgConnection@1c28101
38611.10 17:55:45.614 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
38711.10 17:55:45.614 INFO [JDBCMapperImpl] Commit transaction:
38811.10 17:55:45.614 INFO [JDBCMapperImpl]
38911.10 17:55:45.614 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@28660136 wrapping org.postgresql.jdbc.PgConnection@1c28101
39011.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=?
39111.10 17:55:45.615 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@28660136 wrapping org.postgresql.jdbc.PgConnection@1c28101
39211.10 17:55:45.615 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
39311.10 17:55:45.615 INFO [JDBCMapperImpl] Commit transaction:
39411.10 17:55:45.615 INFO [JDBCMapperImpl]
39511.10 17:55:45.615 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@27736900 wrapping org.postgresql.jdbc.PgConnection@1c28101
39611.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=?
39711.10 17:55:45.624 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@27736900 wrapping org.postgresql.jdbc.PgConnection@1c28101
39811.10 17:55:45.624 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
39911.10 17:55:45.624 INFO [JDBCMapperImpl] Commit transaction:
40011.10 17:55:45.624 INFO [JDBCMapperImpl]
40111.10 17:55:45.624 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@15179985 wrapping org.postgresql.jdbc.PgConnection@1c28101
40211.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=?
40311.10 17:55:45.624 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@15179985 wrapping org.postgresql.jdbc.PgConnection@1c28101
40411.10 17:55:45.625 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
40511.10 17:55:45.625 INFO [JDBCMapperImpl] Commit transaction:
40611.10 17:55:45.625 INFO [JDBCMapperImpl]
40711.10 17:55:45.625 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@26315182 wrapping org.postgresql.jdbc.PgConnection@1c28101
40811.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=?
40911.10 17:55:45.625 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@26315182 wrapping org.postgresql.jdbc.PgConnection@1c28101
41011.10 17:55:45.625 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
41111.10 17:55:45.625 INFO [JDBCMapperImpl] Commit transaction:
41211.10 17:55:45.625 INFO [JDBCMapperImpl]
41311.10 17:55:45.625 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@27028399 wrapping org.postgresql.jdbc.PgConnection@1c28101
41411.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=?
41511.10 17:55:45.625 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@27028399 wrapping org.postgresql.jdbc.PgConnection@1c28101
41611.10 17:55:45.625 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
41711.10 17:55:45.625 INFO [JDBCMapperImpl] Commit transaction:
41811.10 17:55:45.625 INFO [JDBCMapperImpl]
41911.10 17:55:45.625 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@3484556 wrapping org.postgresql.jdbc.PgConnection@1c28101
42011.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=?
42111.10 17:55:45.626 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@3484556 wrapping org.postgresql.jdbc.PgConnection@1c28101
42211.10 17:55:45.627 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
42311.10 17:55:45.627 INFO [JDBCMapperImpl] Commit transaction:
42411.10 17:55:45.627 INFO [JDBCMapperImpl]
42511.10 17:55:45.627 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@19611436 wrapping org.postgresql.jdbc.PgConnection@1c28101
42611.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=?
42711.10 17:55:45.627 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@19611436 wrapping org.postgresql.jdbc.PgConnection@1c28101
42811.10 17:55:45.627 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
42911.10 17:55:45.627 INFO [JDBCMapperImpl] Commit transaction:
43011.10 17:55:45.627 INFO [JDBCMapperImpl]
43111.10 17:55:45.627 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@32873480 wrapping org.postgresql.jdbc.PgConnection@1c28101
43211.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=?
43311.10 17:55:45.628 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@32873480 wrapping org.postgresql.jdbc.PgConnection@1c28101
43411.10 17:55:45.628 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
43511.10 17:55:45.628 INFO [JDBCMapperImpl] Commit transaction:
43611.10 17:55:45.628 INFO [JDBCMapperImpl]
43711.10 17:55:45.628 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@17988902 wrapping org.postgresql.jdbc.PgConnection@1c28101
43811.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=?
43911.10 17:55:45.628 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@17988902 wrapping org.postgresql.jdbc.PgConnection@1c28101
44011.10 17:55:45.628 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
44111.10 17:55:45.628 INFO [JDBCMapperImpl] Commit transaction:
44211.10 17:55:45.628 INFO [JDBCMapperImpl]
44311.10 17:55:45.628 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@22599758 wrapping org.postgresql.jdbc.PgConnection@1c28101
44411.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=?
44511.10 17:55:45.628 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@22599758 wrapping org.postgresql.jdbc.PgConnection@1c28101
44611.10 17:55:45.629 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
44711.10 17:55:45.629 INFO [JDBCMapperImpl] Commit transaction:
44811.10 17:55:45.629 INFO [JDBCMapperImpl]
44911.10 17:55:45.629 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@29132185 wrapping org.postgresql.jdbc.PgConnection@1c28101
45011.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=?
45111.10 17:55:45.629 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@29132185 wrapping org.postgresql.jdbc.PgConnection@1c28101
45211.10 17:55:45.629 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
45311.10 17:55:45.629 INFO [JDBCMapperImpl] Commit transaction:
45411.10 17:55:45.629 INFO [JDBCMapperImpl]
45511.10 17:55:45.629 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@1955346 wrapping org.postgresql.jdbc.PgConnection@1c28101
45611.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=?
45711.10 17:55:45.630 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@1955346 wrapping org.postgresql.jdbc.PgConnection@1c28101
45811.10 17:55:45.630 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
45911.10 17:55:45.630 INFO [JDBCMapperImpl] Commit transaction:
46011.10 17:55:45.630 INFO [JDBCMapperImpl]
46111.10 17:55:45.630 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@20298452 wrapping org.postgresql.jdbc.PgConnection@1c28101
46211.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=?
46311.10 17:55:45.630 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@20298452 wrapping org.postgresql.jdbc.PgConnection@1c28101
46411.10 17:55:45.630 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
46511.10 17:55:45.630 INFO [JDBCMapperImpl] Commit transaction:
46611.10 17:55:45.630 INFO [JDBCMapperImpl]
46711.10 17:55:45.630 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@22455748 wrapping org.postgresql.jdbc.PgConnection@1c28101
46811.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=?
46911.10 17:55:45.630 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@22455748 wrapping org.postgresql.jdbc.PgConnection@1c28101
47011.10 17:55:45.631 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
47111.10 17:55:45.631 INFO [JDBCMapperImpl] Commit transaction:
47211.10 17:55:45.631 INFO [JDBCMapperImpl]
47311.10 17:55:45.631 DEBUG [SetApiGoodsPluginPaymentTypeLimiter] The purchase has no Set API goods
47411.10 17:55:45.631 DEBUG [CheckContainer] CheckContainer.startPayments()
47511.10 17:55:45.631 DEBUG [CheckContainer] State in start payments = ADD_PAYMENT
47611.10 17:55:45.631 DEBUG [CheckContainer] State purchase in start payments = PAYMENTS
47711.10 17:55:45.632 INFO [CheckContainer] startPayments() surcharge = 3600
47811.10 17:55:45.661 DEBUG [Factory] CheckContainer.paymentTypeSelected(ru.crystals.pos.visualization.payments.cash.CashPaymentContainer@14fedad)
47911.10 17:55:45.661 DEBUG [CheckContainer] /CheckContainer/ Trying to set state: ADD_PAYMENT
48011.10 17:55:45.676 INFO [CheckContainer] isPaymentComplete = false
48111.10 17:55:45.677 INFO [CheckContainer] prevState = ADD_POSITION
48211.10 17:55:45.677 INFO [CheckContainer] paid = 0
48311.10 17:55:45.677 INFO [CheckContainer] surcharge = 3600
48411.10 17:55:45.677 INFO [CheckContainer] getPaymentFiscalizeError = NONE
48511.10 17:55:45.677 INFO [CheckContainer] Current payment container is ru.crystals.pos.visualization.payments.cash.CashPaymentContainer
48611.10 17:55:45.678 INFO [CommonLogger] busy = false
48711.10 17:55:45.678 INFO [CommonLogger] busy = false
48811.10 17:55:46.434 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327625]; fileName: null; status: NO_SENT
48911.10 17:55:46.434 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
490SET sent_to_server_status = :status, filename = :fileName
491WHERE id IN (:ids)
49211.10 17:55:46.436 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 2 [ms]
49311.10 17:55:46.437 TRACE [TransferManager] setStatus: [1] loy-txes were updated
49411.10 17:55:46.437 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175543_422_73011_3.ser
49511.10 17:55:46.437 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
49611.10 17:55:46.437 INFO [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
49711.10 17:55:46.437 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
49811.10 17:55:46.926 DEBUG [HikariPool] HikariPool-4 - Pool stats (total=5, active=0, idle=5, waiting=0)
49911.10 17:55:47.313 DEBUG [KeyboardImpl] -> KEY PRESSED: keyCode = 99
50011.10 17:55:47.314 DEBUG [KeyboardImpl] -> KEY TYPED: keyCode = 99, keyChar 3
50111.10 17:55:47.314 DEBUG [KeyboardImpl] ---> KEY TYPED 2_1: keyCode = 51
50211.10 17:55:47.334 DEBUG [KeyboardImpl] keyboard - keysqueue [[Key scanCode=51]]
50311.10 17:55:47.335 INFO [TechProcessImpl] eventAlphaNumericKey: AlphaNumericKey [scanCode=51, character=3]
50411.10 17:55:47.368 DEBUG [KeyboardImpl] -> KEY PRESSED: keyCode = 102
50511.10 17:55:47.369 DEBUG [KeyboardImpl] -> KEY TYPED: keyCode = 102, keyChar 6
50611.10 17:55:47.369 DEBUG [KeyboardImpl] ---> KEY TYPED 2_1: keyCode = 54
50711.10 17:55:47.389 DEBUG [KeyboardImpl] keyboard - keysqueue [[Key scanCode=54]]
50811.10 17:55:47.390 INFO [TechProcessImpl] eventAlphaNumericKey: AlphaNumericKey [scanCode=54, character=6]
50911.10 17:55:47.440 DEBUG [KeyboardImpl] -> KEY RELEASED: keyCode = 99
51011.10 17:55:47.464 DEBUG [KeyboardImpl] -> KEY RELEASED: keyCode = 102
51111.10 17:55:49.001 DEBUG [KeyboardImpl] -> KEY PRESSED: keyCode = 10
51211.10 17:55:49.001 DEBUG [KeyboardImpl] -> KEY TYPED: keyCode = 10, keyChar
513
51411.10 17:55:49.001 DEBUG [KeyboardImpl] ---> KEY TYPED 3: keyCode = 10
51511.10 17:55:49.022 DEBUG [KeyboardImpl] keyboard - keysqueue [[Key scanCode=10]]
51611.10 17:55:49.022 INFO [TechProcessImpl] eventControlKey: ControlKey [scanCode=10, command=kbdEnter]
51711.10 17:55:49.023 INFO [CommonLogger] doProcessPayment() in class ru.crystals.pos.visualization.payments.cash.CashPaymentContainer
51811.10 17:55:49.023 INFO [TechProcessImpl] addPayment CashPaymentEntity 3600
51911.10 17:55:49.038 TRACE [CheckService] last payment added feedbacks: []
52011.10 17:55:49.038 TRACE [CheckService] feedbacks received: []
52111.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 [[]]
52211.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 [[]]
52311.10 17:55:49.038 TRACE [MainWindow] updating receipt...
52411.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]
52511.10 17:55:49.038 TRACE [MainWindow] MW.updateCheck(PurchaseEntity): visual state is: CHECK
52611.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]
52711.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
52811.10 17:55:49.052 INFO [CommonLogger] value = 90
52911.10 17:55:49.056 DEBUG [CheckContainer] CheckContainer.subtotal() - Check state: ADD_PAYMENT, State purchase: PAYMENTS
53011.10 17:55:49.057 TRACE [MainWindow] leaving MW.updateCheck(PurchaseEntity)
53111.10 17:55:49.057 TRACE [MainWindow] leaving purchaseChangedAtPaymentsStage(PurchaseEntity, List). It took 19 [ms]
53211.10 17:55:49.057 TRACE [TechProcessEventsImpl] leaving purchaseChangedAtPaymentsStage(PurchaseEntity, List). It took 19 [ms]
53311.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
53411.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]
53511.10 17:55:49.114 TRACE [Runner] Runner begin work ru.crystals.pos.visualization.Factory$21
53611.10 17:55:49.114 TRACE [Runner] Runner end work ru.crystals.pos.visualization.Factory$21
53711.10 17:55:49.131 DEBUG [KeyboardImpl] -> KEY RELEASED: keyCode = 10
53811.10 17:55:49.133 INFO [FiscalPrinter] getLastKpk
53911.10 17:55:49.134 INFO [FiscalPrinter] LastKpk = 75
54011.10 17:55:49.137 WARN [EgaisExciseValidationImpl] call : sendExciseData()
54111.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]
54211.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]]
54311.10 17:55:49.178 TRACE [HibernateBackedLoyTxDao] loy-tx-id of the receipt is not null: 327962
54411.10 17:55:49.178 TRACE [HibernateBackedLoyTxDao] entering getLoyTxById(long). The argument is: loyTxId [327962]
54511.10 17:55:49.179 TRACE [HibernateBackedLoyTxDao] 1 loy-txes were extracted
54611.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]
54711.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]
54811.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]]
54911.10 17:55:49.200 TRACE [HibernateBackedLoyTxDao] loy-tx-id of the receipt is not null: 327962
55011.10 17:55:49.200 TRACE [HibernateBackedLoyTxDao] entering getLoyTxById(long). The argument is: loyTxId [327962]
55111.10 17:55:49.201 TRACE [HibernateBackedLoyTxDao] 1 loy-txes were extracted
55211.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]
55311.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]
55411.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]]
55511.10 17:55:49.207 TRACE [LoyalServiceImpl] leaving beforeFiscalize(PurchaseEntity). it took 0 [ms]
55611.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]]
55711.10 17:55:49.207 TRACE [HibernateBackedLoyTxDao] loy-tx-id of the receipt is not null: 327962
55811.10 17:55:49.207 TRACE [HibernateBackedLoyTxDao] entering getLoyTxById(long). The argument is: loyTxId [327962]
55911.10 17:55:49.208 TRACE [HibernateBackedLoyTxDao] 1 loy-txes were extracted
56011.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]
56111.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]
56211.10 17:55:49.233 INFO [DocumentTemplate] =====0=====
56311.10 17:55:49.233 INFO [DocumentTemplate] ******************************************"ПАР||NORMAL
56411.10 17:55:49.233 INFO [DocumentTemplate] АД СКИДОК! Не забудьте 1 купон со скидками у ||NORMAL
56511.10 17:55:49.233 INFO [DocumentTemplate] кассира" ||NORMAL
56611.10 17:55:49.233 INFO [FiscalPrinter] openMoneyDrawer
56711.10 17:55:49.234 INFO [FiscalPrinter] setCashDrawerOpen(true)
56811.10 17:55:49.234 INFO [TechProcessImpl] Ящик открыт
56911.10 17:55:49.234 INFO [FiscalPrinter] isMoneyDrawerOpen
57011.10 17:55:49.258 TRACE [LoyalServiceImpl] entering searchDiscountResultsInDB(Long, boolean). The arguments are: loyTransactionId [327962], useCached [false]
57111.10 17:55:49.258 TRACE [HibernateBackedLoyTxDao] entering getLoyTxById(long). The argument is: loyTxId [327962]
57211.10 17:55:49.266 TRACE [HibernateBackedLoyTxDao] 1 loy-txes were extracted
57311.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]
57411.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]
57511.10 17:55:49.271 TRACE [LoyalServiceImpl] get manual advertising actions guids in purchase..
57611.10 17:55:49.271 TRACE [LoyalServiceImpl] number of manual advertising actions guids in purchase = 0
57711.10 17:55:49.271 DEBUG [LoyalServiceImpl] getAdvertisingActions.. number of manual actions = 0
57811.10 17:55:49.271 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
57911.10 17:55:49.271 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:49.271+0300], manualActionGuids: []
58011.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]
58111.10 17:55:49.272 DEBUG [LoyalServiceImpl] time of get active actions: 1
58211.10 17:55:49.272 TRACE [LoyalServiceImpl] get manual advertising actions guids in purchase..
58311.10 17:55:49.272 TRACE [LoyalServiceImpl] number of manual advertising actions guids in purchase = 0
58411.10 17:55:49.272 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
58511.10 17:55:49.272 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:49.272+0300], manualActionGuids: []
58611.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]
58711.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]]
58811.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]]
58911.10 17:55:49.285 TRACE [HibernateBackedLoyTxDao] loy-tx-id of the receipt is not null: 327962
59011.10 17:55:49.285 TRACE [HibernateBackedLoyTxDao] entering getLoyTxById(long). The argument is: loyTxId [327962]
59111.10 17:55:49.286 TRACE [HibernateBackedLoyTxDao] 1 loy-txes were extracted
59211.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]
59311.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]
59411.10 17:55:49.294 DEBUG [SetApiPluginLoyProvider] No loyalty plugins found.
59511.10 17:55:49.295 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@32430607 wrapping org.postgresql.jdbc.PgConnection@1c28101
59611.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
59711.10 17:55:49.296 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@32430607 wrapping org.postgresql.jdbc.PgConnection@1c28101
59811.10 17:55:49.296 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
59911.10 17:55:49.296 INFO [JDBCMapperImpl] Commit transaction:
60011.10 17:55:49.296 INFO [JDBCMapperImpl]
60111.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]]]]]
60211.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]]]]]
60311.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]
60411.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]
60511.10 17:55:49.315 TRACE [LoyalServiceImpl] leaving preparePurchaseFiscalization(PurchaseEntity). it took 30 [ms]
60611.10 17:55:49.315 INFO [FiscalPrinter] printCheck
60711.10 17:55:49.316 INFO [FiscalPrinter] getLastKpk
60811.10 17:55:49.316 INFO [FiscalPrinter] LastKpk = 75
60911.10 17:55:49.316 INFO [FiscalPrinter] Fiscal interrupt: null
61011.10 17:55:49.316 INFO [FiscalPrinter] Get document template /mnt/sda1/tce/storage/crystal-cash/modules/fiscalPrinter/templates/check-sale.xml
61111.10 17:55:49.316 INFO [DocumentTemplate] =====logo=====
61211.10 17:55:49.317 INFO [DocumentTemplate] content: null
61311.10 17:55:49.319 INFO [DocumentTemplate] =====header=====
61411.10 17:55:49.320 INFO [DocumentTemplate] =====position=====
61511.10 17:55:49.320 INFO [DocumentTemplate] НАИМЕНОВАНИЕ | ЦЕНА* |КОЛ-ВО|СУММА БЕЗ СК|С||SMALL
61611.10 17:55:49.320 INFO [DocumentTemplate] Булочки Бородинские 36.00 1 36.90 36.00||SMALL
61711.10 17:55:49.320 INFO [DocumentTemplate] в т.ч. НДС 10.00% СКИДКА= 0.90 РУБ||SMALL
61811.10 17:55:49.320 INFO [DocumentTemplate] в т.ч. НДС НДС 10% % ||SMALL
61911.10 17:55:49.320 INFO [DocumentTemplate] в т.ч. НДС 10.0 % СКИДКА= 0.90 РУБ||SMALL
62011.10 17:55:49.320 INFO [DocumentTemplate] * с учётом всех скидок и НДС ||SMALL
62111.10 17:55:49.320 INFO [DocumentTemplate] =====payment=====
62211.10 17:55:49.320 INFO [DocumentTemplate] =====discount=====
62311.10 17:55:49.320 INFO [DocumentTemplate] ВАША СКИДКА СОСТАВИЛА, руб =0.90||DOUBLEHEIGHT
62411.10 17:55:49.329 INFO [DocumentTemplate] =====includedSlips=====
62511.10 17:55:49.329 INFO [DocumentTemplate] ||NORMAL
62611.10 17:55:49.329 INFO [DocumentTemplate] ******************************************"ПАР||NORMAL
62711.10 17:55:49.329 INFO [DocumentTemplate] АД СКИДОК! Не забудьте 1 купон со скидками у ||NORMAL
62811.10 17:55:49.329 INFO [DocumentTemplate] кассира" ||NORMAL
62911.10 17:55:49.329 INFO [DocumentTemplate] ||NORMAL
63011.10 17:55:49.330 INFO [DocumentTemplate] =====tax=====
63111.10 17:55:49.330 INFO [DocumentTemplate] =====total=====
63211.10 17:55:49.330 INFO [DocumentTemplate] =====fiscal=====
63311.10 17:55:49.330 INFO [DocumentTemplate] content: null
63411.10 17:55:49.330 INFO [DocumentTemplate] =====footer=====
63511.10 17:55:49.330 INFO [DocumentTemplate] =====cut=====
63611.10 17:55:49.330 INFO [DocumentTemplate] content: null
63711.10 17:55:49.330 INFO [DocumentTemplate] =====bonuses=====
63811.10 17:55:49.445 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327626]; fileName: null; status: NO_SENT
63911.10 17:55:49.446 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
640SET sent_to_server_status = :status, filename = :fileName
641WHERE id IN (:ids)
64211.10 17:55:49.447 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 2 [ms]
64311.10 17:55:49.447 TRACE [TransferManager] setStatus: [1] loy-txes were updated
64411.10 17:55:49.447 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175546_437_73011_3.ser
64511.10 17:55:49.447 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
64611.10 17:55:49.447 INFO [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
64711.10 17:55:49.447 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
64811.10 17:55:49.512 INFO [FiscalPrinter] getLastKpk
64911.10 17:55:49.513 INFO [FiscalPrinter] LastKpk = 76
65011.10 17:55:49.513 TRACE [FiscalPrinter] getFiscalCheckData
65111.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]
65211.10 17:55:49.519 TRACE [ExternalProcessingsImpl] entering purchaseFiscalized(PurchaseEntity)
65311.10 17:55:49.519 TRACE [ExternalProcessingsImpl] Purchase fiscalized: no implementation of PlastekServices.
65411.10 17:55:49.519 TRACE [ExternalProcessingsImpl] Purchase fiscalized: no implementation of externalLoyaltyService.
65511.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...
65611.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]]
65711.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]]
65811.10 17:55:49.536 TRACE [HibernateBackedLoyTxDao] loy-tx-id of the receipt is not null: 327962
65911.10 17:55:49.536 TRACE [HibernateBackedLoyTxDao] entering getLoyTxById(long). The argument is: loyTxId [327962]
66011.10 17:55:49.537 TRACE [HibernateBackedLoyTxDao] 1 loy-txes were extracted
66111.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]
66211.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]
66311.10 17:55:49.542 DEBUG [SetApiPluginLoyProvider] No loyalty plugins found.
66411.10 17:55:49.542 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
66511.10 17:55:49.542 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:49.542+0300], manualActionGuids: []
66611.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]
66711.10 17:55:49.543 TRACE [LoyaltyRestrictionsServiceImpl] createApplyRestrictionsRequest: request = NULL
66811.10 17:55:49.543 TRACE [LoyalServiceImpl] get manual advertising actions guids in purchase..
66911.10 17:55:49.543 TRACE [LoyalServiceImpl] number of manual advertising actions guids in purchase = 0
67011.10 17:55:49.543 DEBUG [LoyalServiceImpl] getAdvertisingActions.. number of manual actions = 0
67111.10 17:55:49.543 TRACE [AdvActionsCacheImpl] getActiveActions: lock on cache was obtained in 0 [ms]
67211.10 17:55:49.543 TRACE [AdvActionsCacheImpl] entering getActiveActions(Date, Set). The arguments are: date [2019-10-11T17:55:49.543+0300], manualActionGuids: []
67311.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]
67411.10 17:55:49.544 DEBUG [LoyalServiceImpl] time of get active actions: 1
67511.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]]]]]
67611.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]
67711.10 17:55:49.554 TRACE [LoyalServiceImpl] leaving purchaseFiscalized(PurchaseEntity). it took 19 [ms]
67811.10 17:55:49.554 TRACE [ExternalProcessingsImpl] leaving purchaseFiscalized(PurchaseEntity). It took 35 [ms]
67911.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]]
68011.10 17:55:49.554 TRACE [HibernateBackedLoyTxDao] loy-tx-id of the receipt is not null: 327962
68111.10 17:55:49.554 TRACE [HibernateBackedLoyTxDao] entering getLoyTxById(long). The argument is: loyTxId [327962]
68211.10 17:55:49.555 TRACE [HibernateBackedLoyTxDao] 1 loy-txes were extracted
68311.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]
68411.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]
68511.10 17:55:49.559 DEBUG [ProcessingUniqueCouponManager] issueUniqueCouponsBackground() []
68611.10 17:55:49.562 INFO [FiscalPrinter] printDiscountsReport
68711.10 17:55:49.562 INFO [FiscalPrinter] Get document template /mnt/sda1/tce/storage/crystal-cash/modules/fiscalPrinter/templates/discounts-report.xml
68811.10 17:55:49.562 INFO [DocumentTemplate] =====logo=====
68911.10 17:55:49.562 INFO [DocumentTemplate] content: null
69011.10 17:55:49.563 INFO [DocumentTemplate] =====header=====
69111.10 17:55:49.563 INFO [DocumentTemplate] ||NORMAL
69211.10 17:55:49.563 INFO [DocumentTemplate] ||NORMAL
69311.10 17:55:49.563 INFO [DocumentTemplate] ---------------------------------------- ||NORMAL
69411.10 17:55:49.563 INFO [DocumentTemplate] Смена:10 ЭКЛЗ:769d1811-348||NORMAL
69511.10 17:55:49.563 INFO [DocumentTemplate] Номер кассы:3 ИНН: 7802781104||NORMAL
69611.10 17:55:49.563 INFO [DocumentTemplate] Кассир:Администратор Кассовый 456 ||NORMAL
69711.10 17:55:49.563 INFO [DocumentTemplate] ---------------------------------------- ||NORMAL
69811.10 17:55:49.563 INFO [DocumentTemplate] ОТЧЕТ ПО СКИДКАМ 48 11-10-2019 17:55||NORMAL
69911.10 17:55:49.563 INFO [DocumentTemplate] ---------------------------------------- ||NORMAL
70011.10 17:55:49.563 INFO [DocumentTemplate] =====groupByGoods=====
70111.10 17:55:49.563 INFO [DocumentTemplate] content: null
70211.10 17:55:49.563 INFO [DocumentTemplate] =====groupByAA=====
70311.10 17:55:49.563 INFO [DocumentTemplate] =====checkDiscounts=====
70411.10 17:55:49.563 INFO [DocumentTemplate] ---------------------------------------- ||NORMAL
70511.10 17:55:49.563 INFO [DocumentTemplate] Скидки на чек ||NORMAL
70611.10 17:55:49.563 INFO [DocumentTemplate] ---------------------------------------- ||NORMAL
70711.10 17:55:49.563 INFO [DocumentTemplate] Округление =0.90||SMALL
70811.10 17:55:49.563 INFO [DocumentTemplate] =====total=====
70911.10 17:55:49.563 INFO [DocumentTemplate] ---------------------------------------- ||NORMAL
71011.10 17:55:49.563 INFO [DocumentTemplate] ИТОГО СКИДКА НА ЧЕК =0.90||NORMAL
71111.10 17:55:49.563 INFO [DocumentTemplate] =====fiscal=====
71211.10 17:55:49.563 INFO [DocumentTemplate] content: null
71311.10 17:55:49.563 INFO [DocumentTemplate] =====footer=====
71411.10 17:55:49.563 INFO [DocumentTemplate] Док N:48 11-10-2019 17:55 ||NORMAL
71511.10 17:55:49.563 INFO [DocumentTemplate] Спасибо за покупку! ||NORMAL
71611.10 17:55:49.563 INFO [DocumentTemplate] =====cut=====
71711.10 17:55:49.563 INFO [DocumentTemplate] content: null
71811.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]]
71911.10 17:55:49.590 TRACE [LoyalServiceImpl] entering searchDiscountResultsInDB(Long, boolean). The arguments are: loyTransactionId [327962], useCached [false]
72011.10 17:55:49.590 TRACE [HibernateBackedLoyTxDao] entering getLoyTxById(long). The argument is: loyTxId [327962]
72111.10 17:55:49.591 TRACE [HibernateBackedLoyTxDao] 1 loy-txes were extracted
72211.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]
72311.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]
72411.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]]
72511.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]
72611.10 17:55:49.613 TRACE [SCService] entering isEnabled()
72711.10 17:55:49.613 TRACE [SCService] leaving isEnabled(). the result is: true
72811.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]
72911.10 17:55:49.613 TRACE [SCService] Stop send Personal Offer
73011.10 17:55:49.613 TRACE [SCService] Remove Personal offer feedback
73111.10 17:55:49.613 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@551304 wrapping org.postgresql.jdbc.PgConnection@10e1bdf
73211.10 17:55:49.613 TRACE [JdbcBackedLoyFeedbackDao] Entering remove(documentNum = 48, shiftNum = 10, cashNum = 3, shopNum = 73011, providerName = smch, feedbackTime = UNTIL_NOT_FISCALIZED).
73311.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=?
73411.10 17:55:49.614 TRACE [JdbcBackedLoyFeedbackDao] leaving remove(LoyExtProviderFeedback). The result is: {}
73511.10 17:55:49.614 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@551304 wrapping org.postgresql.jdbc.PgConnection@10e1bdf
73611.10 17:55:49.614 DEBUG [PoolBase] HikariPool-9 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@10e1bdf
73711.10 17:55:49.614 INFO [JDBCMapperImpl] Commit transaction:
73811.10 17:55:49.614 INFO [JDBCMapperImpl]
73911.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]]]]
74011.10 17:55:49.615 TRACE [SCService] Send request <?xml version="1.0" encoding="UTF-8" standalone="yes"?>
741<ChequeRequest xmlns="http://smartcheckout.ru/xsd/s10ren.xsd" ChequeType="Fiscal">
742 <RequestID>1570805730837</RequestID>
743 <Defer>false</Defer>
744 <DateTime>2019-10-11T17:55:49.614+03:00</DateTime>
745 <POS>3</POS>
746 <Number>1570805730837</Number>
747 <Summ>36.90</Summ>
748 <Discount>2.439</Discount>
749 <SummDiscounted>36.00</SummDiscounted>
750 <Item>
751 <PositionNumber>1</PositionNumber>
752 <Article>1300386</Article>
753 <ArticleName>Булочки Бородинские 300г п/п</ArticleName>
754 <Price>36.90</Price>
755 <Quantity>1.000</Quantity>
756 <Summ>36.90</Summ>
757 <Discount>2.439</Discount>
758 <SummDiscounted>36.00</SummDiscounted>
759 <ExtendedAttribute>
760 <Key>DISCOUNT</Key>
761 <Value>2.439</Value>
762 </ExtendedAttribute>
763 </Item>
764</ChequeRequest>
765
76611.10 17:55:49.615 TRACE [SCService] entering getServices()
76711.10 17:55:49.615 TRACE [SCService] getting services (IN MEMORY)
76811.10 17:55:49.615 TRACE [SCService] leaving getServices(). The result size is: 2
76911.10 17:55:49.627 TRACE [SCService] Received response: <?xml version="1.0" encoding="UTF-8" standalone="yes"?>
770<ChequeRequestResponce xmlns="http://smartcheckout.ru/xsd/s10ren.xsd">
771 <RequestID>1570805730837</RequestID>
772 <Processed>2019-10-11T17:55:49.619+03:00</Processed>
773 <ReturnCode>0</ReturnCode>
774 <CashierMessageTO>0</CashierMessageTO>
775 <Summ>36.90</Summ>
776 <Discount>2.439</Discount>
777 <SummDiscounted>36.00</SummDiscounted>
778 <Item>
779 <PositionNumber>1</PositionNumber>
780 <Article>1300386</Article>
781 <ArticleName>Булочки Бородинские 300г п/п</ArticleName>
782 <Price>36.90</Price>
783 <MinPrice>0</MinPrice>
784 <Quantity>1.000</Quantity>
785 <Summ>36.90</Summ>
786 <Discount>2.439</Discount>
787 <SummDiscounted>36.00</SummDiscounted>
788 <ExtendedAttribute>
789 <Key>DISCOUNT</Key>
790 <Value>2.439</Value>
791 </ExtendedAttribute>
792 </Item>
793</ChequeRequestResponce>
794
79511.10 17:55:49.745 INFO [FiscalPrinter] isMoneyDrawerOpen
79611.10 17:55:50.246 INFO [FiscalPrinter] isMoneyDrawerOpen
79711.10 17:55:50.434 DEBUG [HikariPool] HikariPool-5 - Pool stats (total=1, active=0, idle=1, waiting=0)
79811.10 17:55:50.746 INFO [FiscalPrinter] isMoneyDrawerOpen
79911.10 17:55:51.247 INFO [FiscalPrinter] isMoneyDrawerOpen
80011.10 17:55:52.492 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327627]; fileName: null; status: NO_SENT
80111.10 17:55:52.492 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
802SET sent_to_server_status = :status, filename = :fileName
803WHERE id IN (:ids)
80411.10 17:55:52.494 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 2 [ms]
80511.10 17:55:52.494 TRACE [TransferManager] setStatus: [1] loy-txes were updated
80611.10 17:55:52.494 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175549_447_73011_3.ser
80711.10 17:55:52.494 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
80811.10 17:55:52.495 INFO [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
80911.10 17:55:52.495 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
81011.10 17:55:53.822 DEBUG [HikariPool] HikariPool-6 - Pool stats (total=5, active=0, idle=5, waiting=0)
81111.10 17:55:54.945 DEBUG [HikariPool] HikariPool-7 - Pool stats (total=5, active=0, idle=5, waiting=0)
81211.10 17:55:55.223 DEBUG [HikariPool] HikariPool-8 - Pool stats (total=1, active=0, idle=1, waiting=0)
81311.10 17:55:55.498 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327628]; fileName: null; status: NO_SENT
81411.10 17:55:55.499 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
815SET sent_to_server_status = :status, filename = :fileName
816WHERE id IN (:ids)
81711.10 17:55:55.501 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 3 [ms]
81811.10 17:55:55.501 TRACE [TransferManager] setStatus: [1] loy-txes were updated
81911.10 17:55:55.501 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175552_495_73011_3.ser
82011.10 17:55:55.501 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
82111.10 17:55:55.501 INFO [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
82211.10 17:55:55.501 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
82311.10 17:55:57.522 DEBUG [TechProcessImpl] Server offline mode
82411.10 17:55:57.522 TRACE [Runner] Runner begin work ru.crystals.pos.visualization.Factory$10
82511.10 17:55:57.523 TRACE [Runner] Runner end work ru.crystals.pos.visualization.Factory$10
82611.10 17:55:58.503 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327629]; fileName: null; status: NO_SENT
82711.10 17:55:58.503 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
828SET sent_to_server_status = :status, filename = :fileName
829WHERE id IN (:ids)
83011.10 17:55:58.505 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 2 [ms]
83111.10 17:55:58.505 TRACE [TransferManager] setStatus: [1] loy-txes were updated
83211.10 17:55:58.505 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175555_501_73011_3.ser
83311.10 17:55:58.505 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
83411.10 17:55:58.505 INFO [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
83511.10 17:55:58.506 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
83611.10 17:55:59.275 DEBUG [SetApiLoyaltyPluginBackgroundWorker] Queue returned null
83711.10 17:55:59.276 DEBUG [SetApiLoyaltyPluginBackgroundWorker] Queue has no items, returning to polling.
83811.10 17:55:59.276 DEBUG [SetApiLoyaltyPluginBackgroundWorker] Polling...
83911.10 17:55:59.276 INFO [PendingOperationQueue] Pending cards operation queue is empty. Populating from DB...
84011.10 17:55:59.286 INFO [LoyProvidersRegistryImpl] Resend stale feedback
84111.10 17:55:59.286 INFO [LoyProvidersRegistryImpl] looking up LoyFeedbackDao...
84211.10 17:55:59.286 INFO [LoyProvidersRegistryImpl] Search for stale feedback provider = smch
84311.10 17:55:59.286 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@16333118 wrapping org.postgresql.jdbc.PgConnection@10e1bdf
84411.10 17:55:59.287 TRACE [JdbcBackedLoyFeedbackDao] entering getFeedbackByProviderAndTime(providerId, maxCount). The arguments are smch AS_SOON_AS_POSSIBLE
84511.10 17:55:59.287 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@2255873 wrapping SELECT * FROM loy_feedback WHERE provider_id = ? AND feedback_time = ? LIMIT ?
84611.10 17:55:59.287 TRACE [JdbcBackedLoyFeedbackDao] leaving getFeedbackByProviderAndTime(smch). The result is: []
84711.10 17:55:59.288 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@16333118 wrapping org.postgresql.jdbc.PgConnection@10e1bdf
84811.10 17:55:59.288 DEBUG [PoolBase] HikariPool-9 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@10e1bdf
84911.10 17:55:59.288 INFO [JDBCMapperImpl] Commit transaction:
85011.10 17:55:59.288 INFO [JDBCMapperImpl]
85111.10 17:55:59.288 INFO [LoyProvidersRegistryImpl] There is no stale feedback for smch
85211.10 17:55:59.288 INFO [LoyProvidersRegistryImpl] Search for stale feedback provider = SetApiLoyaltyPlugin
85311.10 17:55:59.288 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@31422894 wrapping org.postgresql.jdbc.PgConnection@10e1bdf
85411.10 17:55:59.288 TRACE [JdbcBackedLoyFeedbackDao] entering getFeedbackByProviderAndTime(providerId, maxCount). The arguments are SetApiLoyaltyPlugin AS_SOON_AS_POSSIBLE
85511.10 17:55:59.288 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@285296 wrapping SELECT * FROM loy_feedback WHERE provider_id = ? AND feedback_time = ? LIMIT ?
85611.10 17:55:59.289 TRACE [JdbcBackedLoyFeedbackDao] leaving getFeedbackByProviderAndTime(SetApiLoyaltyPlugin). The result is: []
85711.10 17:55:59.289 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@31422894 wrapping org.postgresql.jdbc.PgConnection@10e1bdf
85811.10 17:55:59.289 DEBUG [PoolBase] HikariPool-9 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@10e1bdf
85911.10 17:55:59.289 INFO [JDBCMapperImpl] Commit transaction:
86011.10 17:55:59.289 INFO [JDBCMapperImpl]
86111.10 17:55:59.289 INFO [LoyProvidersRegistryImpl] There is no stale feedback for SetApiLoyaltyPlugin
86211.10 17:55:59.289 INFO [LoyProvidersRegistryImpl] Search for stale feedback provider = ml
86311.10 17:55:59.289 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@299385 wrapping org.postgresql.jdbc.PgConnection@10e1bdf
86411.10 17:55:59.289 TRACE [JdbcBackedLoyFeedbackDao] entering getFeedbackByProviderAndTime(providerId, maxCount). The arguments are ml AS_SOON_AS_POSSIBLE
86511.10 17:55:59.289 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@12621918 wrapping SELECT * FROM loy_feedback WHERE provider_id = ? AND feedback_time = ? LIMIT ?
86611.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"?>
867<ProcessRequest xmlns="http://loyalty.manzanagroup.ru/loyalty.xsd">
868 <request>
869 <ChequeRequest>
870 <Card>
871 <CardNumber>offlinecard1</CardNumber>
872 </Card>
873 <DateTime>2019-10-11T17:15:04.948+03:00</DateTime>
874 <Organization>1</Organization>
875 <BusinessUnit>SCO</BusinessUnit>
876 <POS>3</POS>
877 <Number>1570803304138</Number>
878 <OperationType>Return</OperationType>
879 <Summ>20.00</Summ>
880 <Discount>0.000</Discount>
881 <SummDiscounted>20.00</SummDiscounted>
882 <Item>
883 <PositionNumber>1</PositionNumber>
884 <Article>1068918</Article>
885 <ArticleName>М/изд Квартал 400г Завитки п/п</ArticleName>
886 <Price>20.00</Price>
887 <Quantity>1.000</Quantity>
888 <Summ>20.00</Summ>
889 <Discount>0.000</Discount>
890 <SummDiscounted>20.00</SummDiscounted>
891 </Item>
892 </ChequeRequest>
893 </request>
894</ProcessRequest>
895}, LoyExtProviderFeedback{id=32784, payload=<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
896<ProcessRequest xmlns="http://loyalty.manzanagroup.ru/loyalty.xsd">
897 <request>
898 <ChequeRequest>
899 <Card>
900 <CardNumber>offlinecard1</CardNumber>
901 </Card>
902 <DateTime>2019-10-11T17:15:22.683+03:00</DateTime>
903 <Organization>1</Organization>
904 <BusinessUnit>SCO</BusinessUnit>
905 <POS>3</POS>
906 <Number>1570803321755</Number>
907 <OperationType>Return</OperationType>
908 <Summ>399.00</Summ>
909 <Discount>0.000</Discount>
910 <SummDiscounted>399.00</SummDiscounted>
911 <Item>
912 <PositionNumber>1</PositionNumber>
913 <Article>1246672</Article>
914 <ArticleName>Десерт Джильдо Рачелли 500г Тирамису</ArticleName>
915 <Price>399.00</Price>
916 <Quantity>1.000</Quantity>
917 <Summ>399.00</Summ>
918 <Discount>0.000</Discount>
919 <SummDiscounted>399.00</SummDiscounted>
920 </Item>
921 </ChequeRequest>
922 </request>
923</ProcessRequest>
924}, LoyExtProviderFeedback{id=32791, payload=<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
925<ProcessRequest xmlns="http://loyalty.manzanagroup.ru/loyalty.xsd">
926 <request>
927 <ChequeRequest>
928 <Card>
929 <CardNumber>offlinecard1</CardNumber>
930 </Card>
931 <DateTime>2019-10-11T17:27:23.802+03:00</DateTime>
932 <Organization>1</Organization>
933 <BusinessUnit>SCO</BusinessUnit>
934 <POS>3</POS>
935 <Number>1570804042558</Number>
936 <OperationType>Return</OperationType>
937 <Summ>39.00</Summ>
938 <Discount>0.000</Discount>
939 <SummDiscounted>39.00</SummDiscounted>
940 <Item>
941 <PositionNumber>1</PositionNumber>
942 <Article>1266040</Article>
943 <ArticleName>Салфетка микрофибра 25*25см Хоум Текстил</ArticleName>
944 <Price>39.00</Price>
945 <Quantity>1.000</Quantity>
946 <Summ>39.00</Summ>
947 <Discount>0.000</Discount>
948 <SummDiscounted>39.00</SummDiscounted>
949 </Item>
950 </ChequeRequest>
951 </request>
952</ProcessRequest>
953}, LoyExtProviderFeedback{id=32795, payload=<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
954<ProcessRequest xmlns="http://loyalty.manzanagroup.ru/loyalty.xsd">
955 <request>
956 <ChequeRequest>
957 <Card>
958 <CardNumber>offlinecard1</CardNumber>
959 </Card>
960 <DateTime>2019-10-11T17:42:34.094+03:00</DateTime>
961 <Organization>1</Organization>
962 <BusinessUnit>SCO</BusinessUnit>
963 <POS>3</POS>
964 <Number>1570804951770</Number>
965 <OperationType>Return</OperationType>
966 <Summ>284.90</Summ>
967 <Discount>0.316</Discount>
968 <SummDiscounted>284.00</SummDiscounted>
969 <Item>
970 <PositionNumber>1</PositionNumber>
971 <Article>1114576</Article>
972 <ArticleName>Чахохбили 4Сезона 600г фасолью</ArticleName>
973 <Price>284.90</Price>
974 <Quantity>1.000</Quantity>
975 <Summ>284.90</Summ>
976 <Discount>0.316</Discount>
977 <SummDiscounted>284.00</SummDiscounted>
978 <ExtendedAttribute>
979 <Key>DISCOUNT</Key>
980 <Value>0.316</Value>
981 </ExtendedAttribute>
982 </Item>
983 </ChequeRequest>
984 </request>
985</ProcessRequest>
986}, LoyExtProviderFeedback{id=32782, payload=<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
987<ProcessRequest xmlns="http://loyalty.manzanagroup.ru/loyalty.xsd">
988 <request>
989 <ChequeRequest>
990 <Card>
991 <CardNumber>offlinecard1</CardNumber>
992 </Card>
993 <DateTime>2019-10-11T17:13:17.133+03:00</DateTime>
994 <Organization>1</Organization>
995 <BusinessUnit>SCO</BusinessUnit>
996 <POS>3</POS>
997 <Number>1570803194586</Number>
998 <OperationType>Return</OperationType>
999 <Summ>84.90</Summ>
1000 <Discount>1.060</Discount>
1001 <SummDiscounted>84.00</SummDiscounted>
1002 <Item>
1003 <PositionNumber>1</PositionNumber>
1004 <Article>1266575</Article>
1005 <ArticleName>Сметана Простоквашино 315г 25% пл/ст</ArticleName>
1006 <Price>84.90</Price>
1007 <Quantity>1.000</Quantity>
1008 <Summ>84.90</Summ>
1009 <Discount>1.060</Discount>
1010 <SummDiscounted>84.00</SummDiscounted>
1011 <ExtendedAttribute>
1012 <Key>DISCOUNT</Key>
1013 <Value>1.060</Value>
1014 </ExtendedAttribute>
1015 </Item>
1016 </ChequeRequest>
1017 </request>
1018</ProcessRequest>
1019}]
102011.10 17:55:59.294 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@299385 wrapping org.postgresql.jdbc.PgConnection@10e1bdf
102111.10 17:55:59.294 DEBUG [PoolBase] HikariPool-9 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@10e1bdf
102211.10 17:55:59.294 INFO [JDBCMapperImpl] Commit transaction:
102311.10 17:55:59.294 INFO [JDBCMapperImpl]
102411.10 17:55:59.294 INFO [LoyProvidersRegistryImpl] Found 5 stale feedback for ml. Submit to executor
102511.10 17:55:59.297 INFO [PendingOperationQueue] No pending card operations found.
102611.10 17:55:59.308 INFO [LoyProvidersRegistryImpl] Search for stale feedback provider = set-loy-provider
102711.10 17:55:59.308 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@22398429 wrapping org.postgresql.jdbc.PgConnection@10e1bdf
102811.10 17:55:59.308 TRACE [JdbcBackedLoyFeedbackDao] entering getFeedbackByProviderAndTime(providerId, maxCount). The arguments are set-loy-provider AS_SOON_AS_POSSIBLE
102911.10 17:55:59.308 DEBUG [JDBCMapperImpl] PreparedStatement = HikariProxyPreparedStatement@18519482 wrapping SELECT * FROM loy_feedback WHERE provider_id = ? AND feedback_time = ? LIMIT ?
103011.10 17:55:59.309 TRACE [JdbcBackedLoyFeedbackDao] leaving getFeedbackByProviderAndTime(set-loy-provider). The result is: []
103111.10 17:55:59.309 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@22398429 wrapping org.postgresql.jdbc.PgConnection@10e1bdf
103211.10 17:55:59.309 DEBUG [PoolBase] HikariPool-9 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@10e1bdf
103311.10 17:55:59.309 INFO [JDBCMapperImpl] Commit transaction:
103411.10 17:55:59.309 INFO [JDBCMapperImpl]
103511.10 17:55:59.309 INFO [LoyProvidersRegistryImpl] There is no stale feedback for set-loy-provider
103611.10 17:55:59.540 DEBUG [HikariPool] HikariPool-9 - Pool stats (total=5, active=0, idle=5, waiting=0)
103711.10 17:56:01.522 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327690]; fileName: null; status: NO_SENT
103811.10 17:56:01.522 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
1039SET sent_to_server_status = :status, filename = :fileName
1040WHERE id IN (:ids)
104111.10 17:56:01.523 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 1 [ms]
104211.10 17:56:01.523 TRACE [TransferManager] setStatus: [1] loy-txes were updated
104311.10 17:56:01.523 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175558_507_73011_3.ser
104411.10 17:56:01.524 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
104511.10 17:56:01.524 INFO [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
104611.10 17:56:01.524 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
104711.10 17:56:04.531 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327691]; fileName: null; status: NO_SENT
104811.10 17:56:04.531 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
1049SET sent_to_server_status = :status, filename = :fileName
1050WHERE id IN (:ids)
105111.10 17:56:04.533 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 2 [ms]
105211.10 17:56:04.533 TRACE [TransferManager] setStatus: [1] loy-txes were updated
105311.10 17:56:04.533 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175601_524_73011_3.ser
105411.10 17:56:04.534 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
105511.10 17:56:04.535 INFO [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
105611.10 17:56:04.536 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
105711.10 17:56:07.542 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327694]; fileName: null; status: NO_SENT
105811.10 17:56:07.542 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
1059SET sent_to_server_status = :status, filename = :fileName
1060WHERE id IN (:ids)
106111.10 17:56:07.546 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 4 [ms]
106211.10 17:56:07.547 TRACE [TransferManager] setStatus: [1] loy-txes were updated
106311.10 17:56:07.547 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175604_536_73011_3.ser
106411.10 17:56:07.548 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
106511.10 17:56:07.548 INFO [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
106611.10 17:56:07.548 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
106711.10 17:56:08.321 DEBUG [HikariPool] HikariPool-1 - Pool stats (total=5, active=0, idle=5, waiting=0)
106811.10 17:56:10.555 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327740]; fileName: null; status: NO_SENT
106911.10 17:56:10.556 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
1070SET sent_to_server_status = :status, filename = :fileName
1071WHERE id IN (:ids)
107211.10 17:56:10.561 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 6 [ms]
107311.10 17:56:10.561 TRACE [TransferManager] setStatus: [1] loy-txes were updated
107411.10 17:56:10.561 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175607_548_73011_3.ser
107511.10 17:56:10.561 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
107611.10 17:56:10.561 INFO [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
107711.10 17:56:10.561 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
107811.10 17:56:10.904 DEBUG [HikariPool] HikariPool-2 - Pool stats (total=5, active=0, idle=5, waiting=0)
107911.10 17:56:11.217 DEBUG [HikariPool] HikariPool-3 - Pool stats (total=5, active=0, idle=5, waiting=0)
108011.10 17:56:11.494 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
108111.10 17:56:11.495 INFO [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
108211.10 17:56:11.495 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
108311.10 17:56:11.495 ERROR [DocumentSender] Send document error:
1084java.net.SocketTimeoutException: connect timed out
1085 at java.net.PlainSocketImpl.socketConnect(Native Method) ~[?:1.8.0_112]
1086 at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350) ~[?:1.8.0_112]
1087 at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206) ~[?:1.8.0_112]
1088 at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188) ~[?:1.8.0_112]
1089 at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) ~[?:1.8.0_112]
1090 at java.net.Socket.connect(Socket.java:589) ~[?:1.8.0_112]
1091 at sun.net.NetworkClient.doConnect(NetworkClient.java:175) ~[?:1.8.0_112]
1092 at sun.net.www.http.HttpClient.openServer(HttpClient.java:432) ~[?:1.8.0_112]
1093 at sun.net.www.http.HttpClient.openServer(HttpClient.java:527) ~[?:1.8.0_112]
1094 at sun.net.www.http.HttpClient.<init>(HttpClient.java:211) ~[?:1.8.0_112]
1095 at sun.net.www.http.HttpClient.New(HttpClient.java:308) ~[?:1.8.0_112]
1096 at sun.net.www.http.HttpClient.New(HttpClient.java:326) ~[?:1.8.0_112]
1097 at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1202) ~[?:1.8.0_112]
1098 at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1138) ~[?:1.8.0_112]
1099 at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1032) ~[?:1.8.0_112]
1100 at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:966) ~[?:1.8.0_112]
1101 at ru.crystals.httpclient.HttpFileTransport.getServerOutputFullAddress(HttpFileTransport.java:51) ~[ServerHttpClient.jar:?]
1102 at ru.crystals.httpclient.HttpFileTransport.getServerOutput(HttpFileTransport.java:40) ~[ServerHttpClient.jar:?]
1103 at ru.crystals.pos.transport.ModuleConnection.getHttpFileOutputConnection(ModuleConnection.java:65) ~[registry.jar:10.2.74.0]
1104 at ru.crystals.pos.check.service.transport.DocumentSender.setDocumentToSet10(DocumentSender.java:377) [document.jar:10.2.74.0]
1105 at ru.crystals.pos.check.service.transport.DocumentSender.sendObject(DocumentSender.java:312) [document.jar:10.2.74.0]
1106 at ru.crystals.pos.check.service.transport.DocumentSender.exportDocuments(DocumentSender.java:194) [document.jar:10.2.74.0]
1107 at ru.crystals.pos.check.service.transport.DocumentSender.run(DocumentSender.java:103) [document.jar:10.2.74.0]
1108 at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_112]
1109 at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_112]
1110 at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_112]
1111 at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_112]
1112 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_112]
1113 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_112]
1114 at java.lang.Thread.run(Thread.java:745) [?:1.8.0_112]
111511.10 17:56:11.497 INFO [JDBCMapperImpl] Start transaction (1): HikariProxyConnection@31517727 wrapping org.postgresql.jdbc.PgConnection@1c28101
111611.10 17:56:11.497 INFO [JDBCMapperImpl] Final close connection HikariProxyConnection@31517727 wrapping org.postgresql.jdbc.PgConnection@1c28101
111711.10 17:56:11.498 DEBUG [PoolBase] HikariPool-3 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1c28101
111811.10 17:56:11.498 INFO [JDBCMapperImpl] Commit transaction:
111911.10 17:56:11.498 INFO [JDBCMapperImpl]
112011.10 17:56:13.566 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327760]; fileName: null; status: NO_SENT
112111.10 17:56:13.566 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
1122SET sent_to_server_status = :status, filename = :fileName
1123WHERE id IN (:ids)
112411.10 17:56:13.569 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 3 [ms]
112511.10 17:56:13.569 TRACE [TransferManager] setStatus: [1] loy-txes were updated
112611.10 17:56:13.569 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175610_561_73011_3.ser
112711.10 17:56:13.570 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
112811.10 17:56:13.570 INFO [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
112911.10 17:56:13.570 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
113011.10 17:56:16.575 TRACE [HibernateBackedLoyTxDao] entering setTxStatusAndFileNames(Collection, String, SentToServerStatus). The argumetns are: ids (1): [327761]; fileName: null; status: NO_SENT
113111.10 17:56:16.575 TRACE [HibernateBackedLoyTxDao] query as string: UPDATE loy_transaction
1132SET sent_to_server_status = :status, filename = :fileName
1133WHERE id IN (:ids)
113411.10 17:56:16.576 TRACE [HibernateBackedLoyTxDao] leaving setTxStatusAndFileNames(Collection, String, SentToServerStatus). The result is: 1; it took 1 [ms]
113511.10 17:56:16.576 TRACE [TransferManager] setStatus: [1] loy-txes were updated
113611.10 17:56:16.576 ERROR [TransferManager] Failed to upload transactions file 3/LoyTransaction_20191011175613_570_73011_3.ser
113711.10 17:56:16.577 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
113811.10 17:56:16.577 INFO [ModuleConnection] Setting transport URL to "http://10.81.255.5:8090/SetXRMI/TransportServlet"
113911.10 17:56:16.577 INFO [ModuleConnection] Try set nginx transport : http://10.81.255.5:8091
114011.10 17:56:16.934 DEBUG [HikariPool] HikariPool-4 - Pool stats (total=5, active=0, idle=5, waiting=0)
1141^C