2018-02-22 18:06:56,904 INFO [primary] SipLogger - ***** SIP Start ***** 2018-02-22 18:06:56,956 INFO [primary] SipCirculationProvider - Using transport provider: MMM.LibrarySystems.Circulation.Transports.TcpTransportProvider 2018-02-22 18:06:56,960 INFO [primary] SipCirculationProvider - Using message formatter: MMM.LibrarySystems.Circulation.SIP.Protocol.MessageFormatter 2018-02-22 18:07:01,542 INFO [primary] App - Assembly: PresentationFramework-SystemXml, 4.0.30319.18408; assembly=4.0.0.0 2018-02-22 18:07:05,384 INFO [primary] App - Assembly: PresentationFramework-SystemData, 4.0.30319.18408; assembly=4.0.0.0 2018-02-22 18:07:05,605 INFO [12] App - Assembly: System.ServiceModel.Channels, 4.0.30319.18408 built by: FX451RTMGREL; assembly=4.0.0.0 2018-02-22 18:07:05,659 INFO [12] App - Assembly: System.IdentityModel, 4.0.30319.18408 built by: FX451RTMGREL; assembly=4.0.0.0 2018-02-22 18:07:05,630 INFO [14] TcpTransportProvider - TCP: Opening connection to: 192.168.200.12:6001 2018-02-22 18:07:05,998 INFO [22] App - Assembly: System.Numerics, 4.0.30319.18408 built by: FX451RTMGREL; assembly=4.0.0.0 2018-02-22 18:07:06,003 INFO [22] App - Assembly: System.Data.OracleClient, 4.0.30319.18408 built by: FX451RTMGREL; assembly=4.0.0.0 2018-02-22 18:07:10,677 INFO [24] SipCirculationProvider - Opened SIP circulation provider with address: 192.168.200.12:6001 2018-02-22 18:07:10,750 INFO [24] SipCirculationProvider - Processing request MMM.LibrarySystems.Circulation.SIP.Messages.LoginRequest and response MMM.LibrarySystems.Circulation.SIP.Messages.LoginResponse 2018-02-22 18:07:10,917 INFO [24] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:07:11,043 TRACE [24] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY1AZF685\r 2018-02-22 18:07:11,100 TRACE [ 5] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 31 41 5A 46 36 38 35 0D 2018-02-22 18:07:11,103 TRACE [ 5] TcpTransportProvider - TCP: 35 bytes written; 40 ms 2018-02-22 18:07:11,373 INFO [31] App - Assembly: Microsoft.CSharp, 4.0.30319.18408; assembly=4.0.0.0 2018-02-22 18:07:11,424 INFO [31] App - Assembly: System.Dynamic, 4.0.30319.18408; assembly=4.0.0.0 2018-02-22 18:07:16,822 DEBUG [primary] App - Startup duration = 41.7s 2018-02-22 18:07:31,357 TRACE [12] TcpTransportProvider - TCP: read 2018-02-22 18:07:31,357 TRACE [12] TcpTransportProvider - TCP: 0 bytes read; 20234 ms 2018-02-22 18:07:31,357 DEBUG [12] SipCirculationProvider - Duration of operation: 20564 ms 2018-02-22 18:07:32,367 WARN [ 5] SipCirculationProvider - Retry #1 2018-02-22 18:07:32,367 INFO [ 5] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:07:32,367 TRACE [ 5] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY1AZF685\r 2018-02-22 18:07:32,367 TRACE [21] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 31 41 5A 46 36 38 35 0D 2018-02-22 18:07:32,367 TRACE [21] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:07:52,874 TRACE [24] TcpTransportProvider - TCP: read 2018-02-22 18:07:52,874 TRACE [24] TcpTransportProvider - TCP: 0 bytes read; 20507 ms 2018-02-22 18:07:52,874 DEBUG [24] SipCirculationProvider - Duration of operation: 20508 ms 2018-02-22 18:07:53,874 WARN [14] SipCirculationProvider - Retry #2 2018-02-22 18:07:53,874 INFO [14] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:07:53,874 TRACE [14] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY1AZF685\r 2018-02-22 18:07:53,874 TRACE [22] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 31 41 5A 46 36 38 35 0D 2018-02-22 18:07:53,874 TRACE [22] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:08:14,383 TRACE [ 5] TcpTransportProvider - TCP: read 2018-02-22 18:08:14,383 TRACE [ 5] TcpTransportProvider - TCP: 0 bytes read; 20509 ms 2018-02-22 18:08:14,383 DEBUG [ 5] SipCirculationProvider - Duration of operation: 20510 ms 2018-02-22 18:08:14,393 INFO [ 5] TcpTransportProvider - TCP: Closing connection to: 192.168.200.12:6001 2018-02-22 18:08:14,393 INFO [ 5] SipCirculationProvider - Closed SIP circulation provider from address: 192.168.200.12:6001 2018-02-22 18:08:14,625 INFO [primary] App - Assembly: PresentationFramework-SystemXmlLinq, 4.0.30319.18408; assembly=4.0.0.0 2018-02-22 18:08:29,505 INFO [24] SipCirculationProvider - Resetting from error state 2018-02-22 18:08:29,505 INFO [24] TcpTransportProvider - TCP: Opening connection to: 192.168.200.12:6001 2018-02-22 18:08:29,505 INFO [28] SipCirculationProvider - Opened SIP circulation provider with address: 192.168.200.12:6001 2018-02-22 18:08:29,505 INFO [28] SipCirculationProvider - Processing request MMM.LibrarySystems.Circulation.SIP.Messages.LoginRequest and response MMM.LibrarySystems.Circulation.SIP.Messages.LoginResponse 2018-02-22 18:08:29,515 INFO [28] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:08:29,515 TRACE [28] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY2AZF684\r 2018-02-22 18:08:29,515 TRACE [36] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 32 41 5A 46 36 38 34 0D 2018-02-22 18:08:29,515 TRACE [36] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:08:50,012 TRACE [24] TcpTransportProvider - TCP: read 2018-02-22 18:08:50,012 TRACE [24] TcpTransportProvider - TCP: 0 bytes read; 20497 ms 2018-02-22 18:08:50,012 DEBUG [24] SipCirculationProvider - Duration of operation: 20501 ms 2018-02-22 18:08:51,022 WARN [24] SipCirculationProvider - Retry #1 2018-02-22 18:08:51,022 INFO [24] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:08:51,032 TRACE [24] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY2AZF684\r 2018-02-22 18:08:51,032 TRACE [ 5] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 32 41 5A 46 36 38 34 0D 2018-02-22 18:08:51,032 TRACE [ 5] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:09:11,530 TRACE [14] TcpTransportProvider - TCP: read 2018-02-22 18:09:11,530 TRACE [14] TcpTransportProvider - TCP: 0 bytes read; 20498 ms 2018-02-22 18:09:11,530 DEBUG [14] SipCirculationProvider - Duration of operation: 20509 ms 2018-02-22 18:09:12,530 WARN [35] SipCirculationProvider - Retry #2 2018-02-22 18:09:12,530 INFO [35] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:09:12,530 TRACE [35] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY2AZF684\r 2018-02-22 18:09:12,530 TRACE [36] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 32 41 5A 46 36 38 34 0D 2018-02-22 18:09:12,530 TRACE [36] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:09:33,034 TRACE [ 4] TcpTransportProvider - TCP: read 2018-02-22 18:09:33,034 TRACE [ 4] TcpTransportProvider - TCP: 0 bytes read; 20504 ms 2018-02-22 18:09:33,034 DEBUG [ 4] SipCirculationProvider - Duration of operation: 20505 ms 2018-02-22 18:09:33,034 INFO [ 4] TcpTransportProvider - TCP: Closing connection to: 192.168.200.12:6001 2018-02-22 18:09:33,034 INFO [ 4] SipCirculationProvider - Closed SIP circulation provider from address: 192.168.200.12:6001 2018-02-22 18:10:33,183 INFO [25] SipCirculationProvider - Resetting from error state 2018-02-22 18:10:33,183 INFO [25] TcpTransportProvider - TCP: Opening connection to: 192.168.200.12:6001 2018-02-22 18:10:33,183 INFO [26] SipCirculationProvider - Opened SIP circulation provider with address: 192.168.200.12:6001 2018-02-22 18:10:33,183 INFO [26] SipCirculationProvider - Processing request MMM.LibrarySystems.Circulation.SIP.Messages.LoginRequest and response MMM.LibrarySystems.Circulation.SIP.Messages.LoginResponse 2018-02-22 18:10:33,203 INFO [26] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:10:33,203 TRACE [26] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY3AZF683\r 2018-02-22 18:10:33,203 TRACE [25] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 33 41 5A 46 36 38 33 0D 2018-02-22 18:10:33,203 TRACE [25] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:10:36,713 TRACE [23] TcpTransportProvider - TCP: read 39 34 31 41 59 33 41 5A 46 44 46 41 0D 0A 2018-02-22 18:10:36,713 TRACE [23] TcpTransportProvider - TCP: 14 bytes read; 3510 ms 2018-02-22 18:10:36,723 TRACE [23] MessageFormatter - Parsing: 941AY3AZFDFA 2018-02-22 18:10:36,743 INFO [23] MessageFormatter - Parsed: [94] Login Response {ok = 1} 2018-02-22 18:10:36,763 DEBUG [23] SipCirculationProvider - Duration of operation: 3578 ms 2018-02-22 18:10:36,793 INFO [23] MessageFormatter - Formatting: [99] SC Status {status code = UnitIsOk, max print width = 30, protocol version = "2.00"} 2018-02-22 18:10:36,793 TRACE [23] MessageFormatter - Formatted: 9900302.00AY4AZFCA2\r 2018-02-22 18:10:36,793 TRACE [22] TcpTransportProvider - TCP: write 39 39 30 30 33 30 32 2E 30 30 41 59 34 41 5A 46 43 41 32 0D 2018-02-22 18:10:36,793 TRACE [22] TcpTransportProvider - TCP: 20 bytes written; 0 ms 2018-02-22 18:10:36,793 TRACE [22] MessageFormatter - Additional data is required to parse message: \n 2018-02-22 18:10:36,803 TRACE [22] TcpTransportProvider - TCP: read 39 38 59 59 59 59 4E 4E 31 30 30 30 30 35 32 30 31 38 30 32 32 32 20 20 20 20 31 38 31 30 35 31 32 2E 30 30 41 4F 4D 41 49 4E 7C 42 58 59 59 59 59 59 59 59 59 59 59 59 4E 59 59 59 59 7C 41 59 34 41 5A 45 45 33 33 0D 0A 2018-02-22 18:10:36,803 TRACE [22] TcpTransportProvider - TCP: 73 bytes read; 10 ms 2018-02-22 18:10:36,813 TRACE [22] MessageFormatter - Skipping 1 extra character(s) in data: \n 2018-02-22 18:10:36,813 TRACE [22] MessageFormatter - Parsing: 98YYYYNN10000520180222 1810512.00AOMAIN|BXYYYYYYYYYYYNYYYY|AY4AZEE33 2018-02-22 18:10:36,833 INFO [22] MessageFormatter - Parsed: [98] ACS Status {on-line status = True, checkin ok = True, checkout ok = True, ACS renewal policy = True, status update ok = False, off-line ok = False, timeout period = 100, retries allowed = 5, date time sync = 2018-02-22 18:10:51, protocol version = "2.00", [AO] institution id = "MAIN", [BX] supported messages = PatronStatus, CheckOut, CheckIn, BlockPatron, ScAcsStatus, RequestResend, Login, PatronInformation, EndPatronSession, FeePaid, ItemInformation, PatronEnable, Hold, Renew, RenewAll} 2018-02-22 18:10:36,833 DEBUG [22] SipCirculationProvider - Duration of operation: 46 ms 2018-02-22 18:10:36,860 INFO [22] SipCirculationProvider - Supported message flags changed to: PatronStatus, CheckOut, CheckIn, BlockPatron, ScAcsStatus, RequestResend, Login, PatronInformation, EndPatronSession, FeePaid, ItemInformation, PatronEnable, Hold, Renew, RenewAll 2018-02-22 18:10:36,860 INFO [22] SipCirculationProvider - Permission flags changed to: CheckInAllowed, CheckOutAllowed, RenewalAllowed 2018-02-22 18:11:58,234 INFO [primary] App - Exiting 2018-02-22 18:11:58,461 INFO [22] MessageFormatter - Formatting: [99] SC Status {status code = ShuttingDown, max print width = 30, protocol version = "2.00"} 2018-02-22 18:11:58,466 TRACE [22] MessageFormatter - Formatted: 9920302.00AY5AZFC9F\r 2018-02-22 18:11:58,466 TRACE [56] TcpTransportProvider - TCP: write 39 39 32 30 33 30 32 2E 30 30 41 59 35 41 5A 46 43 39 46 0D 2018-02-22 18:11:58,466 TRACE [56] TcpTransportProvider - TCP: 20 bytes written; 0 ms 2018-02-22 18:11:58,466 TRACE [56] MessageFormatter - Additional data is required to parse message: \n 2018-02-22 18:11:58,476 TRACE [56] TcpTransportProvider - TCP: read 39 38 59 59 59 59 4E 4E 31 30 30 30 30 35 32 30 31 38 30 32 32 32 20 20 20 20 31 38 31 32 31 33 32 2E 30 30 41 4F 4D 41 49 4E 7C 42 58 59 59 59 59 59 59 59 59 59 59 59 4E 59 59 59 59 7C 41 59 35 41 5A 45 45 33 32 0D 0A 2018-02-22 18:11:58,476 TRACE [56] TcpTransportProvider - TCP: 73 bytes read; 10 ms 2018-02-22 18:11:58,476 TRACE [56] MessageFormatter - Skipping 1 extra character(s) in data: \n 2018-02-22 18:11:58,476 TRACE [56] MessageFormatter - Parsing: 98YYYYNN10000520180222 1812132.00AOMAIN|BXYYYYYYYYYYYNYYYY|AY5AZEE32 2018-02-22 18:11:58,486 INFO [56] MessageFormatter - Parsed: [98] ACS Status {on-line status = True, checkin ok = True, checkout ok = True, ACS renewal policy = True, status update ok = False, off-line ok = False, timeout period = 100, retries allowed = 5, date time sync = 2018-02-22 18:12:13, protocol version = "2.00", [AO] institution id = "MAIN", [BX] supported messages = PatronStatus, CheckOut, CheckIn, BlockPatron, ScAcsStatus, RequestResend, Login, PatronInformation, EndPatronSession, FeePaid, ItemInformation, PatronEnable, Hold, Renew, RenewAll} 2018-02-22 18:11:58,486 DEBUG [56] SipCirculationProvider - Duration of operation: 30 ms 2018-02-22 18:11:58,486 INFO [56] TcpTransportProvider - TCP: Closing connection to: 192.168.200.12:6001 2018-02-22 18:11:58,486 INFO [56] SipCirculationProvider - Closed SIP circulation provider from address: 192.168.200.12:6001 2018-02-22 18:11:59,348 INFO [primary] App - End 2018-02-22 18:14:06,600 INFO [primary] SipLogger - ***** SIP Start ***** 2018-02-22 18:14:06,646 INFO [primary] SipCirculationProvider - Using transport provider: MMM.LibrarySystems.Circulation.Transports.TcpTransportProvider 2018-02-22 18:14:06,648 INFO [primary] SipCirculationProvider - Using message formatter: MMM.LibrarySystems.Circulation.SIP.Protocol.MessageFormatter 2018-02-22 18:14:11,051 INFO [primary] App - Assembly: PresentationFramework-SystemXml, 4.0.30319.18408; assembly=4.0.0.0 2018-02-22 18:14:14,542 INFO [primary] App - Assembly: PresentationFramework-SystemData, 4.0.30319.18408; assembly=4.0.0.0 2018-02-22 18:14:14,867 INFO [19] TcpTransportProvider - TCP: Opening connection to: 192.168.200.12:6001 2018-02-22 18:14:15,033 INFO [13] SipCirculationProvider - Opened SIP circulation provider with address: 192.168.200.12:6001 2018-02-22 18:14:15,082 INFO [ 3] App - Assembly: System.ServiceModel.Channels, 4.0.30319.18408 built by: FX451RTMGREL; assembly=4.0.0.0 2018-02-22 18:14:15,247 INFO [ 3] App - Assembly: System.IdentityModel, 4.0.30319.18408 built by: FX451RTMGREL; assembly=4.0.0.0 2018-02-22 18:14:15,273 INFO [13] SipCirculationProvider - Processing request MMM.LibrarySystems.Circulation.SIP.Messages.LoginRequest and response MMM.LibrarySystems.Circulation.SIP.Messages.LoginResponse 2018-02-22 18:14:15,389 INFO [20] App - Assembly: System.Numerics, 4.0.30319.18408 built by: FX451RTMGREL; assembly=4.0.0.0 2018-02-22 18:14:15,415 INFO [20] App - Assembly: System.Data.OracleClient, 4.0.30319.18408 built by: FX451RTMGREL; assembly=4.0.0.0 2018-02-22 18:14:15,516 INFO [13] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:14:15,590 TRACE [13] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY1AZF685\r 2018-02-22 18:14:15,677 TRACE [19] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 31 41 5A 46 36 38 35 0D 2018-02-22 18:14:15,692 TRACE [19] TcpTransportProvider - TCP: 35 bytes written; 79 ms 2018-02-22 18:14:21,913 INFO [33] App - Assembly: Microsoft.CSharp, 4.0.30319.18408; assembly=4.0.0.0 2018-02-22 18:14:21,943 INFO [33] App - Assembly: System.Dynamic, 4.0.30319.18408; assembly=4.0.0.0 2018-02-22 18:14:24,522 DEBUG [primary] App - Startup duration = 38.8s 2018-02-22 18:14:41,860 TRACE [18] TcpTransportProvider - TCP: read 2018-02-22 18:14:41,860 TRACE [18] TcpTransportProvider - TCP: 0 bytes read; 26141 ms 2018-02-22 18:14:41,860 DEBUG [18] SipCirculationProvider - Duration of operation: 26454 ms 2018-02-22 18:14:42,870 WARN [ 3] SipCirculationProvider - Retry #1 2018-02-22 18:14:42,870 INFO [ 3] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:14:42,870 TRACE [ 3] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY1AZF685\r 2018-02-22 18:14:42,870 TRACE [24] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 31 41 5A 46 36 38 35 0D 2018-02-22 18:14:42,870 TRACE [24] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:14:53,260 INFO [primary] App - Assembly: PresentationFramework-SystemXmlLinq, 4.0.30319.18408; assembly=4.0.0.0 2018-02-22 18:14:56,672 INFO [primary] App - Assembly: Accessibility, 4.0.30319.18408 built by: FX451RTMGREL; assembly=4.0.0.0 2018-02-22 18:14:59,462 INFO [primary] App - Assembly: SelfCheck.Configurator, 1.70.0.20; assembly=1.70.0.0 2018-02-22 18:15:03,372 TRACE [ 4] TcpTransportProvider - TCP: read 2018-02-22 18:15:03,372 TRACE [ 4] TcpTransportProvider - TCP: 0 bytes read; 20502 ms 2018-02-22 18:15:03,372 DEBUG [ 4] SipCirculationProvider - Duration of operation: 20502 ms 2018-02-22 18:15:04,382 WARN [24] SipCirculationProvider - Retry #2 2018-02-22 18:15:04,382 INFO [24] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:15:04,392 TRACE [24] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY1AZF685\r 2018-02-22 18:15:04,392 TRACE [ 3] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 31 41 5A 46 36 38 35 0D 2018-02-22 18:15:04,392 TRACE [ 3] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:15:24,902 TRACE [18] TcpTransportProvider - TCP: read 2018-02-22 18:15:24,902 TRACE [18] TcpTransportProvider - TCP: 0 bytes read; 20510 ms 2018-02-22 18:15:24,902 DEBUG [18] SipCirculationProvider - Duration of operation: 20522 ms 2018-02-22 18:15:24,912 INFO [18] TcpTransportProvider - TCP: Closing connection to: 192.168.200.12:6001 2018-02-22 18:15:24,912 INFO [18] SipCirculationProvider - Closed SIP circulation provider from address: 192.168.200.12:6001 2018-02-22 18:15:39,981 INFO [ 5] SipCirculationProvider - Resetting from error state 2018-02-22 18:15:39,981 INFO [ 5] TcpTransportProvider - TCP: Opening connection to: 192.168.200.12:6001 2018-02-22 18:15:39,981 INFO [32] SipCirculationProvider - Opened SIP circulation provider with address: 192.168.200.12:6001 2018-02-22 18:15:39,981 INFO [32] SipCirculationProvider - Processing request MMM.LibrarySystems.Circulation.SIP.Messages.LoginRequest and response MMM.LibrarySystems.Circulation.SIP.Messages.LoginResponse 2018-02-22 18:15:39,981 INFO [32] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:15:39,981 TRACE [32] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY2AZF684\r 2018-02-22 18:15:39,981 TRACE [ 3] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 32 41 5A 46 36 38 34 0D 2018-02-22 18:15:39,991 TRACE [ 3] TcpTransportProvider - TCP: 35 bytes written; 10 ms 2018-02-22 18:16:00,491 TRACE [18] TcpTransportProvider - TCP: read 2018-02-22 18:16:00,491 TRACE [18] TcpTransportProvider - TCP: 0 bytes read; 20500 ms 2018-02-22 18:16:00,491 DEBUG [18] SipCirculationProvider - Duration of operation: 20506 ms 2018-02-22 18:16:01,501 WARN [27] SipCirculationProvider - Retry #1 2018-02-22 18:16:01,501 INFO [27] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:16:01,501 TRACE [27] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY2AZF684\r 2018-02-22 18:16:01,501 TRACE [18] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 32 41 5A 46 36 38 34 0D 2018-02-22 18:16:01,501 TRACE [18] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:16:22,004 TRACE [23] TcpTransportProvider - TCP: read 2018-02-22 18:16:22,004 TRACE [23] TcpTransportProvider - TCP: 0 bytes read; 20503 ms 2018-02-22 18:16:22,004 DEBUG [23] SipCirculationProvider - Duration of operation: 20504 ms 2018-02-22 18:16:23,014 WARN [ 4] SipCirculationProvider - Retry #2 2018-02-22 18:16:23,014 INFO [ 4] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:16:23,014 TRACE [ 4] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY2AZF684\r 2018-02-22 18:16:23,014 TRACE [20] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 32 41 5A 46 36 38 34 0D 2018-02-22 18:16:23,014 TRACE [20] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:16:43,524 TRACE [23] TcpTransportProvider - TCP: read 2018-02-22 18:16:43,524 TRACE [23] TcpTransportProvider - TCP: 0 bytes read; 20510 ms 2018-02-22 18:16:43,524 DEBUG [23] SipCirculationProvider - Duration of operation: 20510 ms 2018-02-22 18:16:43,524 INFO [23] TcpTransportProvider - TCP: Closing connection to: 192.168.200.12:6001 2018-02-22 18:16:43,524 INFO [23] SipCirculationProvider - Closed SIP circulation provider from address: 192.168.200.12:6001 2018-02-22 18:17:43,669 INFO [ 4] SipCirculationProvider - Resetting from error state 2018-02-22 18:17:43,669 INFO [ 4] TcpTransportProvider - TCP: Opening connection to: 192.168.200.12:6001 2018-02-22 18:17:43,679 INFO [33] SipCirculationProvider - Opened SIP circulation provider with address: 192.168.200.12:6001 2018-02-22 18:17:43,679 INFO [33] SipCirculationProvider - Processing request MMM.LibrarySystems.Circulation.SIP.Messages.LoginRequest and response MMM.LibrarySystems.Circulation.SIP.Messages.LoginResponse 2018-02-22 18:17:43,699 INFO [33] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:17:43,699 TRACE [33] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY3AZF683\r 2018-02-22 18:17:43,709 TRACE [ 7] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 33 41 5A 46 36 38 33 0D 2018-02-22 18:17:43,709 TRACE [ 7] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:18:04,183 TRACE [ 7] TcpTransportProvider - TCP: read 2018-02-22 18:18:04,183 TRACE [ 7] TcpTransportProvider - TCP: 0 bytes read; 20474 ms 2018-02-22 18:18:04,183 DEBUG [ 7] SipCirculationProvider - Duration of operation: 20502 ms 2018-02-22 18:18:05,200 WARN [ 4] SipCirculationProvider - Retry #1 2018-02-22 18:18:05,200 INFO [ 4] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:18:05,200 TRACE [ 4] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY3AZF683\r 2018-02-22 18:18:05,200 TRACE [13] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 33 41 5A 46 36 38 33 0D 2018-02-22 18:18:05,200 TRACE [13] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:18:25,706 TRACE [ 4] TcpTransportProvider - TCP: read 2018-02-22 18:18:25,706 TRACE [ 4] TcpTransportProvider - TCP: 0 bytes read; 20506 ms 2018-02-22 18:18:25,706 DEBUG [ 4] SipCirculationProvider - Duration of operation: 20506 ms 2018-02-22 18:18:26,716 WARN [26] SipCirculationProvider - Retry #2 2018-02-22 18:18:26,716 INFO [26] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:18:26,716 TRACE [26] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY3AZF683\r 2018-02-22 18:18:26,716 TRACE [ 5] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 33 41 5A 46 36 38 33 0D 2018-02-22 18:18:26,716 TRACE [ 5] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:18:47,223 TRACE [26] TcpTransportProvider - TCP: read 2018-02-22 18:18:47,223 TRACE [26] TcpTransportProvider - TCP: 0 bytes read; 20507 ms 2018-02-22 18:18:47,223 DEBUG [26] SipCirculationProvider - Duration of operation: 20508 ms 2018-02-22 18:18:47,223 INFO [26] TcpTransportProvider - TCP: Closing connection to: 192.168.200.12:6001 2018-02-22 18:18:47,223 INFO [26] SipCirculationProvider - Closed SIP circulation provider from address: 192.168.200.12:6001 2018-02-22 18:19:47,235 INFO [ 5] SipCirculationProvider - Resetting from error state 2018-02-22 18:19:47,235 INFO [ 5] TcpTransportProvider - TCP: Opening connection to: 192.168.200.12:6001 2018-02-22 18:19:47,245 INFO [33] SipCirculationProvider - Opened SIP circulation provider with address: 192.168.200.12:6001 2018-02-22 18:19:47,245 INFO [33] SipCirculationProvider - Processing request MMM.LibrarySystems.Circulation.SIP.Messages.LoginRequest and response MMM.LibrarySystems.Circulation.SIP.Messages.LoginResponse 2018-02-22 18:19:47,245 INFO [33] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:19:47,245 TRACE [33] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY4AZF682\r 2018-02-22 18:19:47,245 TRACE [20] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 34 41 5A 46 36 38 32 0D 2018-02-22 18:19:47,245 TRACE [20] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:20:07,755 TRACE [30] TcpTransportProvider - TCP: read 2018-02-22 18:20:07,755 TRACE [30] TcpTransportProvider - TCP: 0 bytes read; 20510 ms 2018-02-22 18:20:07,755 DEBUG [30] SipCirculationProvider - Duration of operation: 20509 ms 2018-02-22 18:20:08,765 WARN [ 5] SipCirculationProvider - Retry #1 2018-02-22 18:20:08,765 INFO [ 5] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:20:08,765 TRACE [ 5] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY4AZF682\r 2018-02-22 18:20:08,765 TRACE [26] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 34 41 5A 46 36 38 32 0D 2018-02-22 18:20:08,765 TRACE [26] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:20:29,270 TRACE [ 7] TcpTransportProvider - TCP: read 2018-02-22 18:20:29,270 TRACE [ 7] TcpTransportProvider - TCP: 0 bytes read; 20505 ms 2018-02-22 18:20:29,270 DEBUG [ 7] SipCirculationProvider - Duration of operation: 20505 ms 2018-02-22 18:20:30,280 WARN [ 5] SipCirculationProvider - Retry #2 2018-02-22 18:20:30,280 INFO [ 5] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:20:30,290 TRACE [ 5] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY4AZF682\r 2018-02-22 18:20:30,290 TRACE [32] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 34 41 5A 46 36 38 32 0D 2018-02-22 18:20:30,290 TRACE [32] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:20:50,781 TRACE [32] TcpTransportProvider - TCP: read 2018-02-22 18:20:50,781 TRACE [32] TcpTransportProvider - TCP: 0 bytes read; 20491 ms 2018-02-22 18:20:50,781 DEBUG [32] SipCirculationProvider - Duration of operation: 20501 ms 2018-02-22 18:20:50,781 INFO [32] TcpTransportProvider - TCP: Closing connection to: 192.168.200.12:6001 2018-02-22 18:20:50,781 INFO [32] SipCirculationProvider - Closed SIP circulation provider from address: 192.168.200.12:6001 2018-02-22 18:21:50,789 INFO [20] SipCirculationProvider - Resetting from error state 2018-02-22 18:21:50,789 INFO [20] TcpTransportProvider - TCP: Opening connection to: 192.168.200.12:6001 2018-02-22 18:21:50,789 INFO [13] SipCirculationProvider - Opened SIP circulation provider with address: 192.168.200.12:6001 2018-02-22 18:21:50,789 INFO [13] SipCirculationProvider - Processing request MMM.LibrarySystems.Circulation.SIP.Messages.LoginRequest and response MMM.LibrarySystems.Circulation.SIP.Messages.LoginResponse 2018-02-22 18:21:50,789 INFO [13] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:21:50,799 TRACE [13] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY5AZF681\r 2018-02-22 18:21:50,799 TRACE [32] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 35 41 5A 46 36 38 31 0D 2018-02-22 18:21:50,799 TRACE [32] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:22:11,301 TRACE [ 7] TcpTransportProvider - TCP: read 2018-02-22 18:22:11,301 TRACE [ 7] TcpTransportProvider - TCP: 0 bytes read; 20502 ms 2018-02-22 18:22:11,301 DEBUG [ 7] SipCirculationProvider - Duration of operation: 20509 ms 2018-02-22 18:22:12,308 WARN [30] SipCirculationProvider - Retry #1 2018-02-22 18:22:12,328 INFO [30] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:22:12,338 TRACE [30] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY5AZF681\r 2018-02-22 18:22:12,338 TRACE [ 7] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 35 41 5A 46 36 38 31 0D 2018-02-22 18:22:12,338 TRACE [ 7] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:22:32,817 TRACE [ 5] TcpTransportProvider - TCP: read 2018-02-22 18:22:32,818 TRACE [ 5] TcpTransportProvider - TCP: 0 bytes read; 20480 ms 2018-02-22 18:22:32,819 DEBUG [ 5] SipCirculationProvider - Duration of operation: 20510 ms 2018-02-22 18:22:33,829 WARN [ 7] SipCirculationProvider - Retry #2 2018-02-22 18:22:33,834 INFO [ 7] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:22:33,841 TRACE [ 7] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY5AZF681\r 2018-02-22 18:22:33,842 TRACE [ 7] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 35 41 5A 46 36 38 31 0D 2018-02-22 18:22:33,842 TRACE [ 7] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:22:54,339 TRACE [ 7] TcpTransportProvider - TCP: read 2018-02-22 18:22:54,339 TRACE [ 7] TcpTransportProvider - TCP: 0 bytes read; 20496 ms 2018-02-22 18:22:54,339 DEBUG [ 7] SipCirculationProvider - Duration of operation: 20510 ms 2018-02-22 18:22:54,339 INFO [ 7] TcpTransportProvider - TCP: Closing connection to: 192.168.200.12:6001 2018-02-22 18:22:54,339 INFO [ 7] SipCirculationProvider - Closed SIP circulation provider from address: 192.168.200.12:6001 2018-02-22 18:23:54,347 INFO [ 7] SipCirculationProvider - Resetting from error state 2018-02-22 18:23:54,347 INFO [ 7] TcpTransportProvider - TCP: Opening connection to: 192.168.200.12:6001 2018-02-22 18:23:54,347 INFO [13] SipCirculationProvider - Opened SIP circulation provider with address: 192.168.200.12:6001 2018-02-22 18:23:54,347 INFO [13] SipCirculationProvider - Processing request MMM.LibrarySystems.Circulation.SIP.Messages.LoginRequest and response MMM.LibrarySystems.Circulation.SIP.Messages.LoginResponse 2018-02-22 18:23:54,357 INFO [13] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:23:54,378 TRACE [13] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY6AZF680\r 2018-02-22 18:23:54,378 TRACE [ 4] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 36 41 5A 46 36 38 30 0D 2018-02-22 18:23:54,378 TRACE [ 4] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:24:14,857 TRACE [ 4] TcpTransportProvider - TCP: read 2018-02-22 18:24:14,859 TRACE [ 4] TcpTransportProvider - TCP: 0 bytes read; 20481 ms 2018-02-22 18:24:14,861 DEBUG [ 4] SipCirculationProvider - Duration of operation: 20506 ms 2018-02-22 18:24:15,874 WARN [26] SipCirculationProvider - Retry #1 2018-02-22 18:24:15,874 INFO [26] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:24:15,874 TRACE [26] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY6AZF680\r 2018-02-22 18:24:15,874 TRACE [ 3] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 36 41 5A 46 36 38 30 0D 2018-02-22 18:24:15,874 TRACE [ 3] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:24:36,384 TRACE [30] TcpTransportProvider - TCP: read 2018-02-22 18:24:36,384 TRACE [30] TcpTransportProvider - TCP: 0 bytes read; 20510 ms 2018-02-22 18:24:36,384 DEBUG [30] SipCirculationProvider - Duration of operation: 20510 ms 2018-02-22 18:24:37,404 WARN [38] SipCirculationProvider - Retry #2 2018-02-22 18:24:37,404 INFO [38] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:24:37,404 TRACE [38] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY6AZF680\r 2018-02-22 18:24:37,404 TRACE [24] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 36 41 5A 46 36 38 30 0D 2018-02-22 18:24:37,404 TRACE [24] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:24:57,914 TRACE [18] TcpTransportProvider - TCP: read 2018-02-22 18:24:57,914 TRACE [18] TcpTransportProvider - TCP: 0 bytes read; 20510 ms 2018-02-22 18:24:57,914 DEBUG [18] SipCirculationProvider - Duration of operation: 20510 ms 2018-02-22 18:24:57,914 INFO [18] TcpTransportProvider - TCP: Closing connection to: 192.168.200.12:6001 2018-02-22 18:24:57,914 INFO [18] SipCirculationProvider - Closed SIP circulation provider from address: 192.168.200.12:6001 2018-02-22 18:25:57,930 INFO [30] SipCirculationProvider - Resetting from error state 2018-02-22 18:25:57,930 INFO [30] TcpTransportProvider - TCP: Opening connection to: 192.168.200.12:6001 2018-02-22 18:25:57,930 INFO [13] SipCirculationProvider - Opened SIP circulation provider with address: 192.168.200.12:6001 2018-02-22 18:25:57,930 INFO [13] SipCirculationProvider - Processing request MMM.LibrarySystems.Circulation.SIP.Messages.LoginRequest and response MMM.LibrarySystems.Circulation.SIP.Messages.LoginResponse 2018-02-22 18:25:57,930 INFO [13] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:25:57,940 TRACE [13] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY7AZF67F\r 2018-02-22 18:25:57,940 TRACE [38] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 37 41 5A 46 36 37 46 0D 2018-02-22 18:25:57,940 TRACE [38] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:26:18,432 TRACE [25] TcpTransportProvider - TCP: read 2018-02-22 18:26:18,432 TRACE [25] TcpTransportProvider - TCP: 0 bytes read; 20492 ms 2018-02-22 18:26:18,432 DEBUG [25] SipCirculationProvider - Duration of operation: 20498 ms 2018-02-22 18:26:19,442 WARN [25] SipCirculationProvider - Retry #1 2018-02-22 18:26:19,442 INFO [25] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:26:19,442 TRACE [25] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY7AZF67F\r 2018-02-22 18:26:19,442 TRACE [25] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 37 41 5A 46 36 37 46 0D 2018-02-22 18:26:19,442 TRACE [25] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:26:39,950 TRACE [24] TcpTransportProvider - TCP: read 2018-02-22 18:26:39,950 TRACE [24] TcpTransportProvider - TCP: 0 bytes read; 20508 ms 2018-02-22 18:26:39,950 DEBUG [24] SipCirculationProvider - Duration of operation: 20509 ms 2018-02-22 18:26:40,950 WARN [ 7] SipCirculationProvider - Retry #2 2018-02-22 18:26:40,950 INFO [ 7] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:26:40,970 TRACE [ 7] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY7AZF67F\r 2018-02-22 18:26:40,970 TRACE [ 4] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 37 41 5A 46 36 37 46 0D 2018-02-22 18:26:40,970 TRACE [ 4] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:27:01,453 TRACE [ 4] TcpTransportProvider - TCP: read 2018-02-22 18:27:01,453 TRACE [ 4] TcpTransportProvider - TCP: 0 bytes read; 20483 ms 2018-02-22 18:27:01,453 DEBUG [ 4] SipCirculationProvider - Duration of operation: 20504 ms 2018-02-22 18:27:01,453 INFO [ 4] TcpTransportProvider - TCP: Closing connection to: 192.168.200.12:6001 2018-02-22 18:27:01,453 INFO [ 4] SipCirculationProvider - Closed SIP circulation provider from address: 192.168.200.12:6001 2018-02-22 18:28:01,469 INFO [38] SipCirculationProvider - Resetting from error state 2018-02-22 18:28:01,469 INFO [38] TcpTransportProvider - TCP: Opening connection to: 192.168.200.12:6001 2018-02-22 18:28:01,469 INFO [13] SipCirculationProvider - Opened SIP circulation provider with address: 192.168.200.12:6001 2018-02-22 18:28:01,469 INFO [13] SipCirculationProvider - Processing request MMM.LibrarySystems.Circulation.SIP.Messages.LoginRequest and response MMM.LibrarySystems.Circulation.SIP.Messages.LoginResponse 2018-02-22 18:28:01,469 INFO [13] MessageFormatter - Formatting: [93] Login {UID algorithm = 0, PWD algorithm = 0, [CN] login user id = "sip1", [CO] login password = "sip1", [CP] location code = "MAIN"} 2018-02-22 18:28:01,469 TRACE [13] MessageFormatter - Formatted: 9300CNsip1|COsip1|CPMAIN|AY8AZF67E\r 2018-02-22 18:28:01,469 TRACE [18] TcpTransportProvider - TCP: write 39 33 30 30 43 4E 73 69 70 31 7C 43 4F 73 69 70 31 7C 43 50 4D 41 49 4E 7C 41 59 38 41 5A 46 36 37 45 0D 2018-02-22 18:28:01,469 TRACE [18] TcpTransportProvider - TCP: 35 bytes written; 0 ms 2018-02-22 18:28:01,529 TRACE [25] TcpTransportProvider - TCP: read 39 34 31 41 59 38 41 5A 46 44 46 35 0D 0A 2018-02-22 18:28:01,529 TRACE [25] TcpTransportProvider - TCP: 14 bytes read; 60 ms 2018-02-22 18:28:01,539 TRACE [25] MessageFormatter - Parsing: 941AY8AZFDF5 2018-02-22 18:28:01,549 INFO [25] MessageFormatter - Parsed: [94] Login Response {ok = 1} 2018-02-22 18:28:01,559 DEBUG [25] SipCirculationProvider - Duration of operation: 95 ms 2018-02-22 18:28:01,579 INFO [25] MessageFormatter - Formatting: [99] SC Status {status code = UnitIsOk, max print width = 30, protocol version = "2.00"} 2018-02-22 18:28:01,579 TRACE [25] MessageFormatter - Formatted: 9900302.00AY9AZFC9D\r 2018-02-22 18:28:01,589 TRACE [19] TcpTransportProvider - TCP: write 39 39 30 30 33 30 32 2E 30 30 41 59 39 41 5A 46 43 39 44 0D 2018-02-22 18:28:01,589 TRACE [19] TcpTransportProvider - TCP: 20 bytes written; 0 ms 2018-02-22 18:28:01,589 TRACE [19] MessageFormatter - Additional data is required to parse message: \n 2018-02-22 18:28:01,589 TRACE [37] TcpTransportProvider - TCP: read 39 38 59 59 59 59 4E 4E 31 30 30 30 30 35 32 30 31 38 30 32 32 32 20 20 20 20 31 38 32 38 31 36 32 2E 30 30 41 4F 4D 41 49 4E 7C 42 58 59 59 59 59 59 59 59 59 59 59 59 4E 59 59 59 59 7C 41 59 39 41 5A 45 45 32 34 0D 0A 2018-02-22 18:28:01,589 TRACE [37] TcpTransportProvider - TCP: 73 bytes read; 0 ms 2018-02-22 18:28:01,589 TRACE [37] MessageFormatter - Skipping 1 extra character(s) in data: \n 2018-02-22 18:28:01,589 TRACE [37] MessageFormatter - Parsing: 98YYYYNN10000520180222 1828162.00AOMAIN|BXYYYYYYYYYYYNYYYY|AY9AZEE24 2018-02-22 18:28:01,609 INFO [37] MessageFormatter - Parsed: [98] ACS Status {on-line status = True, checkin ok = True, checkout ok = True, ACS renewal policy = True, status update ok = False, off-line ok = False, timeout period = 100, retries allowed = 5, date time sync = 2018-02-22 18:28:16, protocol version = "2.00", [AO] institution id = "MAIN", [BX] supported messages = PatronStatus, CheckOut, CheckIn, BlockPatron, ScAcsStatus, RequestResend, Login, PatronInformation, EndPatronSession, FeePaid, ItemInformation, PatronEnable, Hold, Renew, RenewAll} 2018-02-22 18:28:01,609 DEBUG [37] SipCirculationProvider - Duration of operation: 30 ms 2018-02-22 18:28:01,619 INFO [37] SipCirculationProvider - Supported message flags changed to: PatronStatus, CheckOut, CheckIn, BlockPatron, ScAcsStatus, RequestResend, Login, PatronInformation, EndPatronSession, FeePaid, ItemInformation, PatronEnable, Hold, Renew, RenewAll 2018-02-22 18:28:01,619 INFO [37] SipCirculationProvider - Permission flags changed to: CheckInAllowed, CheckOutAllowed, RenewalAllowed 2018-02-22 18:32:09,744 INFO [primary] App - Exiting 2018-02-22 18:32:09,880 INFO [26] MessageFormatter - Formatting: [99] SC Status {status code = ShuttingDown, max print width = 30, protocol version = "2.00"} 2018-02-22 18:32:09,884 TRACE [26] MessageFormatter - Formatted: 9920302.00AY0AZFCA4\r 2018-02-22 18:32:09,884 TRACE [31] TcpTransportProvider - TCP: write 39 39 32 30 33 30 32 2E 30 30 41 59 30 41 5A 46 43 41 34 0D 2018-02-22 18:32:09,885 TRACE [31] TcpTransportProvider - TCP: 20 bytes written; 1 ms 2018-02-22 18:32:09,886 TRACE [31] MessageFormatter - Additional data is required to parse message: \n 2018-02-22 18:32:09,887 TRACE [31] TcpTransportProvider - TCP: read 39 38 59 59 59 59 4E 4E 31 30 30 30 30 35 32 30 31 38 30 32 32 32 20 20 20 20 31 38 33 32 32 34 32 2E 30 30 41 4F 4D 41 49 4E 7C 42 58 59 59 59 59 59 59 59 59 59 59 59 4E 59 59 59 59 7C 41 59 30 41 5A 45 45 33 33 0D 0A 2018-02-22 18:32:09,887 TRACE [31] TcpTransportProvider - TCP: 73 bytes read; 1 ms 2018-02-22 18:32:09,887 TRACE [31] MessageFormatter - Skipping 1 extra character(s) in data: \n 2018-02-22 18:32:09,888 TRACE [31] MessageFormatter - Parsing: 98YYYYNN10000520180222 1832242.00AOMAIN|BXYYYYYYYYYYYNYYYY|AY0AZEE33 2018-02-22 18:32:09,896 INFO [31] MessageFormatter - Parsed: [98] ACS Status {on-line status = True, checkin ok = True, checkout ok = True, ACS renewal policy = True, status update ok = False, off-line ok = False, timeout period = 100, retries allowed = 5, date time sync = 2018-02-22 18:32:24, protocol version = "2.00", [AO] institution id = "MAIN", [BX] supported messages = PatronStatus, CheckOut, CheckIn, BlockPatron, ScAcsStatus, RequestResend, Login, PatronInformation, EndPatronSession, FeePaid, ItemInformation, PatronEnable, Hold, Renew, RenewAll} 2018-02-22 18:32:09,896 DEBUG [31] SipCirculationProvider - Duration of operation: 17 ms 2018-02-22 18:32:09,897 INFO [31] TcpTransportProvider - TCP: Closing connection to: 192.168.200.12:6001 2018-02-22 18:32:09,897 INFO [31] SipCirculationProvider - Closed SIP circulation provider from address: 192.168.200.12:6001 2018-02-22 18:32:10,536 INFO [primary] App - End