Closed msilcox closed 1 week ago
Apart from the timeouts connecting to the inverter at the bottom, this looks like a normal GivTCP startup log.
And you say the soc etc is appearing in home assistant so the connection errors must have been temporary. If you look at the ha history you should see the inverter time sensor being updated regularly.
The log doesn't show any errors related to solcast but I suspect I know what the problem is, solcast have introduced connection limits for the hobbyist accounts and it's likely therefore that the request is being rejected due to solcast throttling.
Looking at the GivTCP configuration there does not look to be any capability to change when the solcast poll is attempted, setting to a random time can help avoid the throttling
Might be better to change to the Solcast integration which does auto retries
I can see that it attempted to set the charge last night based on forecast (minimum is set to 25% for summer months), but this morning the battery is at 4% and I see no charging overnight
2024-07-10 23:21:00,891 - Inv1 - palm_soc - [INFO ] - SoC Chart Data - Start. Paste these lines into a spreadsheet to create a plot of SoC
2024-07-10 23:21:00,891 - Inv1 - palm_soc - [INFO ] - ['Time', '00:00', '00:30', '01:00', '01:30', '02:00', '02:30', '03:00', '03:30', '04:00', '04:30', '05:00', '05:30', '06:00', '06:30', '07:00', '07:30', '08:00', '08:30', '09:00', '09:30', '10:00', '10:30', '11:00', '11:30', '12:00', '12:30', '13:00', '13:30', '14:00', '14:30', '15:00', '15:30', '16:00', '16:30', '17:00', '17:30', '18:00', '18:30', '19:00', '19:30', '20:00', '20:30', '21:00', '21:30', '22:00', '22:30', '23:00', '23:30', '24:00', '24:30', '25:00', '25:30', '26:00', '26:30', '27:00', '27:30', '28:00', '28:30', '29:00', '29:30', '30:00', '30:30', '31:00', '31:30', '32:00', '32:30', '33:00', '33:30', '34:00', '34:30', '35:00', '35:30', '36:00', '36:30', '37:00', '37:30', '38:00', '38:30', '39:00', '39:30', '40:00', '40:30', '41:00', '41:30', '42:00', '42:30', '43:00', '43:30', '44:00', '44:30', '45:00', '45:30', '46:00', '46:30', '47:00', '47:30']
2024-07-10 23:21:00,891 - Inv1 - palm_soc - [INFO ] - ['Calculated SoC', 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 6, 8, 12, 16, 22, 28, 35, 42, 49, 57, 64, 71, 79, 86, 93, 100, 107, 113, 118, 122, 126, 128, 131, 132, 133, 134, 134, 134, 134, 134, 134, 134, 134, 134, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 5, 5, 6, 8, 9, 11, 14, 17, 21, 25, 29, 34, 39, 44, 49, 54, 59, 63, 67, 70, 73, 76, 78, 79, 80, 81, 82, 82, 82, 82, 82, 82, 82, 82, 82]
2024-07-10 23:21:00,891 - Inv1 - palm_soc - [INFO ] - ['Adjusted SoC', 29, 29, 29, 29, 29, 29, 29, 29, 29, 29, 29, 29, 29, 29, 31, 33, 37, 41, 47, 53, 60, 67, 74, 82, 89, 96, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100]
2024-07-10 23:21:00,891 - Inv1 - palm_soc - [INFO ] - ['Max', 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100]
2024-07-10 23:21:00,892 - Inv1 - palm_soc - [INFO ] - ['Reserve', 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4]
2024-07-10 23:21:00,892 - Inv1 - palm_soc - [INFO ] - SoC Chart Data - End
2024-07-10 23:21:01,089 - Inv1 - write - [INFO ] - Setting Charge Target to: 25
2024-07-10 23:21:02,830 - Inv1 - write - [INFO ] - Setting Charge Target 25 was a success
2024-07-10 23:30:21,495 - Inv1 - read - [INFO ] - Saving current energy stats at start of night rate tariff (Dynamic)
2024-07-10 23:45:29,143 - Inv1 - sync - [ERROR ] - Connection to (192.168.1.252, 8899) failed: timed out
2024-07-10 23:45:31,646 - Inv1 - sync - [ERROR ] - Connection to (192.168.1.252, 8899) failed: timed out
2024-07-11 00:00:14,959 - Inv1 - read - [CRITICAL] - Midnight, so resetting Day/Night stats...
2024-07-11 00:00:51,429 - Inv1 - read - [CRITICAL] - Midnight, so resetting Day/Night stats...
2024-07-11 02:36:02,419 - Inv1 - sync - [ERROR ] - Connection to (192.168.1.252, 8899) failed: timed out
2024-07-11 02:37:53,597 - Inv1 - sync - [ERROR ] - Connection to (192.168.1.252, 8899) failed: timed out
2024-07-11 02:37:56,100 - Inv1 - sync - [ERROR ] - Connection to (192.168.1.252, 8899) failed: timed out
2024-07-11 02:37:58,603 - Inv1 - sync - [ERROR ] - Connection to (192.168.1.252, 8899) failed: timed out
2024-07-11 02:38:01,107 - Inv1 - sync - [ERROR ] - Connection to (192.168.1.252, 8899) failed: timed out
2024-07-11 02:38:03,611 - Inv1 - sync - [ERROR ] - Connection to (192.168.1.252, 8899) failed: timed out
2024-07-11 02:38:06,115 - Inv1 - sync - [ERROR ] - Connection to (192.168.1.252, 8899) failed: timed out
2024-07-11 05:30:20,854 - Inv1 - read - [INFO ] - Saving current energy stats at start of day rate tariff (Dynamic)
2024-07-11 07:13:11,889 - Inv1 - sync - [ERROR ] - Connection to (192.168.1.252, 8899) failed: timed out
2024-07-11 07:13:14,392 - Inv1 - sync - [ERROR ] - Connection to (192.168.1.252, 8899) failed: timed out
2024-07-11 07:13:16,895 - Inv1 - sync - [ERROR ] - Connection to (192.168.1.252, 8899) failed: timed out
2024-07-11 07:52:53,249 - Inv1 - sync - [ERROR ] - Connection to (192.168.1.252, 8899) failed: timed out
2024-07-11 07:52:55,752 - Inv1 - sync - [ERROR ] - Connection to (192.168.1.252, 8899) failed: timed out
2024-07-11 07:52:58,256 - Inv1 - sync - [ERROR ] - Connection to (192.168.1.252, 8899) failed: timed out
2024-07-11 07:53:00,759 - Inv1 - sync - [ERROR ] - Connection to (192.168.1.252, 8899) failed: timed out
Ah yes,forgot that there is a minimum summer charge.
It loooks like it sent the first part of the charge series of commands to the inverter OK and then thereafter just got connection errors.
Those connection errors could be the source of the problem. The inverter is presumably wifi connected.
Can you boost the signal near the inverter? Is there a wifi repeater you can connect it to?
I've managed to improve the signal to the inverter - so seeing less timeouts than before. Still not getting the charge set overnight.
Tested this morning with Debug logging enabled (changed the overnight start/end) and can see GivTCP claiming to set the charge successfully but nothing is happening. Current SoC is 10% and it was supposed to be setting to 86%.
logs:
2024-07-16 08:43:02,969 - palm_soc - [DEBUG] - Setting Charge Target to: 86%
2024-07-16 08:43:02,974 - queue - [DEBUG] - Pushed job a88a3b10-2c2d-40f1-9e59-6039bf04bee5 into GivTCP_1
2024-07-16 08:43:02,975 - palm_soc - [DEBUG] - <Job a88a3b10-2c2d-40f1-9e59-6039bf04bee5: write.setChargeTarget({'chargeToPercent': 86})>
2024-07-16 08:43:02,975 - palm_soc - [INFO] - SoC Chart Data - Start. Paste these lines into a spreadsheet to create a plot of SoC
2024-07-16 08:43:02,975 - palm_soc - [INFO] - ['Time', '00:00', '00:30', '01:00', '01:30', '02:00', '02:30', '03:00', '03:30', '04:00', '04:30', '05:00', '05:30', '06:00', '06:30', '07:00', '07:30', '08:00', '08:30', '09:00', '09:30', '10:00', '10:30', '11:00', '11:30', '12:00', '12:30', '13:00', '13:30', '14:00', '14:30', '15:00', '15:30', '16:00', '16:30', '17:00', '17:30', '18:00', '18:30', '19:00', '19:30', '20:00', '20:30', '21:00', '21:30', '22:00', '22:30', '23:00', '23:30', '24:00', '24:30', '25:00', '25:30', '26:00', '26:30', '27:00', '27:30', '28:00', '28:30', '29:00', '29:30', '30:00', '30:30', '31:00', '31:30', '32:00', '32:30', '33:00', '33:30', '34:00', '34:30', '35:00', '35:30', '36:00', '36:30', '37:00', '37:30', '38:00', '38:30', '39:00', '39:30', '40:00', '40:30', '41:00', '41:30', '42:00', '42:30', '43:00', '43:30', '44:00', '44:30', '45:00', '45:30', '46:00', '46:30', '47:00', '47:30']
2024-07-16 08:43:02,976 - palm_soc - [INFO] - ['Calculated SoC', 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 5, 7, 7, 7, 9, 10, 10, 10, 12, 13, 14, 14, 12, 11, 8, 6, 0, -2, -5, -6, -8, -10, -12, -13, -14, -15, -16, -17, -17, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 10, 16, 21, 26, 31, 36, 41, 45, 49, 53, 55, 57, 57, 56, 55, 52, 47, 44, 41, 39, 37, 35, 33, 32, 31, 31, 30, 29, 29]
2024-07-16 08:43:02,976 - palm_soc - [INFO] - ['Adjusted SoC', 90, 90, 90, 90, 90, 90, 90, 90, 90, 90, 90, 90, 90, 90, 90, 90, 90, 90, 90, 91, 93, 93, 93, 95, 96, 96, 96, 98, 99, 100, 100, 98, 97, 94, 92, 86, 84, 81, 80, 78, 76, 74, 73, 72, 71, 70, 69, 69, 69, 69, 69, 69, 69, 69, 69, 69, 69, 69, 69, 69, 69, 69, 69, 69, 69, 69, 69, 75, 81, 86, 91, 96, 100, 100, 100, 100, 100, 100, 100, 100, 99, 98, 95, 90, 87, 84, 82, 80, 78, 76, 75, 74, 74, 73, 72, 72]
2024-07-16 08:43:02,976 - palm_soc - [INFO] - ['Max', 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100, 100]
2024-07-16 08:43:02,976 - palm_soc - [INFO] - ['Reserve', 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4, 4]
2024-07-16 08:43:02,976 - palm_soc - [INFO] - SoC Chart Data - End
2024-07-16 08:43:03,159 - write - [INFO] - Setting Charge Target to: 86
2024-07-16 08:43:03,160 - queue - [DEBUG] - Pushed job 270aaadd-6ed9-441f-b863-4428504f2206 into GivTCP_1
2024-07-16 08:43:03,345 - sync - [DEBUG] - Connection to Modbus server established. Socket ('192.168.1.228', 34163)
2024-07-16 08:43:03,345 - transaction - [DEBUG] - Current transaction state - IDLE
2024-07-16 08:43:03,346 - transaction - [DEBUG] - Running transaction 1
2024-07-16 08:43:03,346 - sync - [DEBUG] - New Transaction state 'SENDING'
2024-07-16 08:43:03,522 - transaction - [DEBUG] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2024-07-16 08:43:03,522 - payload - [DEBUG] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x12']
2024-07-16 08:43:03,522 - transaction - [DEBUG] - Adding transaction 1
2024-07-16 08:43:03,522 - transaction - [DEBUG] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2024-07-16 08:43:03,522 - transaction - [DEBUG] - Current transaction state - TRANSACTION_COMPLETE
2024-07-16 08:43:03,522 - transaction - [DEBUG] - Running transaction 2
2024-07-16 08:43:03,522 - sync - [DEBUG] - New Transaction state 'SENDING'
2024-07-16 08:43:03,696 - transaction - [DEBUG] - Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2024-07-16 08:43:03,696 - payload - [DEBUG] - [b'\x00\x00', b'\x00\x00', b'\x00\x00', b'\x00\x12']
2024-07-16 08:43:03,696 - transaction - [DEBUG] - Adding transaction 2
2024-07-16 08:43:03,696 - transaction - [DEBUG] - Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2024-07-16 08:43:03,697 - mqtt - [DEBUG] - Connecting to broker: core-mosquitto
2024-07-16 08:43:03,697 - mqtt - [DEBUG] - In wait loop
2024-07-16 08:43:03,898 - mqtt - [DEBUG] - In wait loop
2024-07-16 08:43:04,098 - mqtt - [DEBUG] - In wait loop
2024-07-16 08:43:04,299 - mqtt - [DEBUG] - In wait loop
2024-07-16 08:43:04,500 - mqtt - [DEBUG] - In wait loop
2024-07-16 08:43:04,699 - mqtt - [DEBUG] - connected OK Returned code=0
2024-07-16 08:43:04,701 - write - [INFO] - Setting Charge Target 86 was a success
2024-07-16 08:43:18,011 - read - [DEBUG] - ----------------------------Starting----------------------------
2024-07-16 08:43:18,011 - read - [DEBUG] - Getting All Registers
2024-07-16 08:43:18,012 - read - [DEBUG] - Connecting to: 192.168.1.252
2024-07-16 08:43:18,013 - queue - [DEBUG] - Pushed job ae4ee72c-a6b1-4ee1-a9c4-1d5f0dd09e49 into GivTCP_1
Good job on improving the wifi signal, that will definitely help.
Tested this morning with Debug logging enabled (changed the overnight start/end) and can see GivTCP claiming to set the charge successfully but nothing is happening. Current SoC is 10% and it was supposed to be setting to 86%.
In the log I can see it says it sets 'charge target' to 86%. Bit of a weird number as that's not in the battery SoC or Max data predictions. Would have thought it would be the Max value.
I'm not massively familiar with this code, but from how I manage givtcp manually it could well be number.givtcp_SERIALNO_target_soc - can you see if that has changed?
I'm wondering if it has not actually programmed the charge yet but has queued up a future job that will set the charging:
2024-07-16 08:43:18,013 - queue - [DEBUG] - Pushed job ae4ee72c-a6b1-4ee1-a9c4-1d5f0dd09e49 into GivTCP_1
Some things with givtcp like doing a forced charge or a forced discharge (selectors with options like 2, 5, 15, 60 to select the time period of the charge/discharge) it programs the job and then queues up a job to cancel it at the end. This looks similar. If you plot the projected SoC data from the log into a graph when is it due to start the charging at, and maybe wait until then?
I'd also look at select.givtcp_SERIALNO_charge_start_time_slot_1 and end_time_slot_1 which should be (or will be if its a future queued job) be the times that the charge is scheduled for. Again, have these changed to match the palm charging.
I can see the SoC changing this morning during my test, but not the charge time slot (it's charging from solar only). It also didn't update either overnight (overnight charging should be between 23:30 and 05:30).
overnight charging should be between 23:30 and 05:30
I'm assuming you're saying this because this is the times you have set the cheap rate to in the GivTCP configuration?
As a suggestion, try manually setting the start and end time slots yourself and see if GivTCP/palm then starts the charging in that period?
Otherwise I'm running out of ideas, sorry
Decided to switch to using predbat for the solar forecasting charging prediction and it's working fine now.
Running 2.4.3 on HA (2024.7.1) add-on (I have no backup to restore older version) and over the last few days the target charge from solcast has not been updated.
I have tried resetting the Inverter to defaults via the portal with no success. I have tried setting old firmware both on and off (Inverter firmware is D0.450-A0.451) Can connect to the Inverter in the app using local connection and am getting readings for current SoC and charge rate in HA.
Logs from today's restart: