feat(sync): Implement auto-reset for permanently_failed entities and add retry backoff logic
- Added logic to reset permanently_failed entities that have reached their auto-reset threshold in `beteiligte_sync_cron_step.py`. - Enhanced event handling in `beteiligte_sync_event_step.py` to skip retries if the next retry time has not been reached. - Introduced validation checks after sync operations to ensure data consistency and integrity. - Created detailed documentation outlining the fixes and their impacts on the sync process. - Added scripts for analyzing sync issues and comparing entities to facilitate debugging and validation.
This commit is contained in:
417
bitbylaw/docs/SYNC_FIXES_2026-02-08.md
Normal file
417
bitbylaw/docs/SYNC_FIXES_2026-02-08.md
Normal file
@@ -0,0 +1,417 @@
|
||||
# Sync Fixes - 8. Februar 2026
|
||||
|
||||
## Übersicht
|
||||
|
||||
Behebung kritischer Sync-Probleme die bei Analyse von Entity 104860 identifiziert wurden.
|
||||
|
||||
---
|
||||
|
||||
## 🔴 **Problem #11: Initial Sync Logic** - FIXED ✅
|
||||
|
||||
### Problem
|
||||
Initial Sync bevorzugte blind EspoCRM, auch wenn Advoware Entity bereits existierte und neuer war.
|
||||
|
||||
### Fix
|
||||
```python
|
||||
# Vorher (beteiligte_sync_utils.py):
|
||||
if not last_sync:
|
||||
return 'espocrm_newer' # Blind EspoCRM bevorzugt
|
||||
|
||||
# Nachher:
|
||||
if not last_sync:
|
||||
# Vergleiche Timestamps wenn verfügbar
|
||||
if espo_ts and advo_ts:
|
||||
if espo_ts > advo_ts:
|
||||
return 'espocrm_newer'
|
||||
elif advo_ts > espo_ts:
|
||||
return 'advoware_newer'
|
||||
else:
|
||||
return 'no_change'
|
||||
# Fallback: Bevorzuge den mit Timestamp
|
||||
# Nur wenn keine Timestamps: EspoCRM bevorzugen
|
||||
```
|
||||
|
||||
### Impact
|
||||
- ✅ Initiale Syncs respektieren jetzt tatsächliche Änderungszeiten
|
||||
- ✅ Keine ungewollten Überschreibungen mehr bei existierenden Advoware-Entities
|
||||
|
||||
---
|
||||
|
||||
## 🟡 **Problem #12: Max Retry Blockade** - FIXED ✅
|
||||
|
||||
### Problem
|
||||
Nach 5 Fehlversuchen → `permanently_failed` ohne Wiederherstellung bei temporären Fehlern.
|
||||
|
||||
### Fix
|
||||
|
||||
#### 1. Exponential Backoff
|
||||
```python
|
||||
# Neue Konstanten:
|
||||
RETRY_BACKOFF_MINUTES = [1, 5, 15, 60, 240] # 1min, 5min, 15min, 1h, 4h
|
||||
AUTO_RESET_HOURS = 24
|
||||
|
||||
# Bei jedem Retry:
|
||||
backoff_minutes = RETRY_BACKOFF_MINUTES[retry_count - 1]
|
||||
next_retry = now_utc + timedelta(minutes=backoff_minutes)
|
||||
update_data['syncNextRetry'] = next_retry
|
||||
```
|
||||
|
||||
#### 2. Auto-Reset nach 24h
|
||||
```python
|
||||
# Bei permanently_failed:
|
||||
auto_reset_time = now_utc + timedelta(hours=24)
|
||||
update_data['syncAutoResetAt'] = auto_reset_time
|
||||
```
|
||||
|
||||
#### 3. Cron Auto-Reset
|
||||
```python
|
||||
# beteiligte_sync_cron_step.py - Neuer Query:
|
||||
permanently_failed_filter = {
|
||||
'where': [
|
||||
{'type': 'equals', 'attribute': 'syncStatus', 'value': 'permanently_failed'},
|
||||
{'type': 'before', 'attribute': 'syncAutoResetAt', 'value': threshold_str}
|
||||
]
|
||||
}
|
||||
|
||||
# Reset Status zurück zu 'failed' für normalen Retry
|
||||
```
|
||||
|
||||
#### 4. Backoff-Check im Event Handler
|
||||
```python
|
||||
# beteiligte_sync_event_step.py:
|
||||
if sync_next_retry and now_utc < next_retry_ts:
|
||||
# Überspringe Entity bis Backoff-Zeit erreicht
|
||||
return
|
||||
```
|
||||
|
||||
### Impact
|
||||
- ✅ Temporäre Fehler führen nicht mehr zu permanenten Blockaden
|
||||
- ✅ Intelligentes Retry-Verhalten (nicht alle 15min bei jedem Fehler)
|
||||
- ✅ Automatische Wiederherstellung nach 24h
|
||||
- ✅ Reduzierte API-Last bei wiederkehrenden Fehlern
|
||||
|
||||
### Neue EspoCRM Felder erforderlich
|
||||
- `syncNextRetry` (datetime) - Nächster Retry-Zeitpunkt
|
||||
- `syncAutoResetAt` (datetime) - Auto-Reset Zeitpunkt für permanently_failed
|
||||
|
||||
---
|
||||
|
||||
## 🔴 **Problem #13: Keine Validierung** - FIXED ✅
|
||||
|
||||
### Problem
|
||||
Sync-Prozess markierte Entity als `syncStatus='clean'` ohne zu validieren ob Daten wirklich identisch sind.
|
||||
|
||||
**Konkretes Beispiel (Entity 104860)**:
|
||||
- EspoCRM Name: `"Max3 Mustermann"`
|
||||
- Advoware Name: `"22Test8 GmbH"`
|
||||
- syncStatus: `"clean"` ❌
|
||||
|
||||
### Fix
|
||||
|
||||
#### 1. Neue Validierungs-Methode
|
||||
```python
|
||||
# beteiligte_sync_utils.py:
|
||||
async def validate_sync_result(
|
||||
entity_id: str,
|
||||
betnr: int,
|
||||
mapper,
|
||||
direction: str = 'to_advoware'
|
||||
) -> Tuple[bool, Optional[str]]:
|
||||
"""Round-Trip Verification nach Sync"""
|
||||
|
||||
# Lade beide Entities erneut
|
||||
espo_entity = await self.espocrm.get_entity(...)
|
||||
advo_entity = await advoware_api.api_call(...)
|
||||
|
||||
# Validiere kritische Felder
|
||||
critical_fields = ['name', 'rechtsform']
|
||||
differences = []
|
||||
|
||||
if direction == 'to_advoware':
|
||||
# Prüfe ob Advoware die EspoCRM-Werte hat
|
||||
for field in critical_fields:
|
||||
if espo_val != advo_val:
|
||||
differences.append(...)
|
||||
|
||||
return (len(differences) == 0, error_message)
|
||||
```
|
||||
|
||||
#### 2. Integration in Event Handler
|
||||
```python
|
||||
# beteiligte_sync_event_step.py - nach jedem Sync:
|
||||
|
||||
# EspoCRM → Advoware
|
||||
await advoware.put_beteiligte(...)
|
||||
validation_success, validation_error = await sync_utils.validate_sync_result(
|
||||
entity_id, betnr, mapper, direction='to_advoware'
|
||||
)
|
||||
|
||||
if not validation_success:
|
||||
await sync_utils.release_sync_lock(
|
||||
entity_id, 'failed',
|
||||
error_message=f"Validation failed: {validation_error}",
|
||||
increment_retry=True
|
||||
)
|
||||
return
|
||||
```
|
||||
|
||||
### Impact
|
||||
- ✅ Sync-Fehler werden jetzt erkannt (z.B. read-only Felder, Permission-Fehler)
|
||||
- ✅ User wird über Validierungs-Fehler informiert (via `syncErrorMessage`)
|
||||
- ✅ Retry-Logik greift bei Validierungs-Fehlern
|
||||
- ✅ Verhindert "clean"-Status bei inkonsistenten Daten
|
||||
|
||||
---
|
||||
|
||||
## 🔴 **Problem #3: Hash-Berechnung inkorrekt** - FIXED ✅
|
||||
|
||||
### Problem
|
||||
Hash beinhaltete ALLE Kommunikationen statt nur sync-relevante.
|
||||
|
||||
**Konkretes Beispiel (Entity 104860)**:
|
||||
- Total: 9 Kommunikationen
|
||||
- Sync-relevant: 4 Kommunikationen
|
||||
- Hash basierte auf: 9 ❌
|
||||
- Hash sollte basieren auf: 4 ✅
|
||||
|
||||
### Fix
|
||||
```python
|
||||
# kommunikation_sync_utils.py:
|
||||
|
||||
# Vorher:
|
||||
komm_rowids = sorted([k.get('rowId', '') for k in advo_kommunikationen if k.get('rowId')])
|
||||
|
||||
# Nachher:
|
||||
sync_relevant_komm = [
|
||||
k for k in advo_kommunikationen
|
||||
if should_sync_to_espocrm(k)
|
||||
]
|
||||
komm_rowids = sorted([k.get('rowId', '') for k in sync_relevant_komm if k.get('rowId')])
|
||||
|
||||
# Logging:
|
||||
self.logger.info(f"Updated hash: {new_hash} (based on {len(sync_relevant_komm)} sync-relevant of {len(advo_kommunikationen)} total)")
|
||||
```
|
||||
|
||||
### Impact
|
||||
- ✅ Hash ändert sich nur bei tatsächlichen Sync-relevanten Änderungen
|
||||
- ✅ Keine false-positives mehr (Sync wird nicht mehr bei irrelevanten Änderungen getriggert)
|
||||
- ✅ Reduzierte API-Last
|
||||
|
||||
---
|
||||
|
||||
## 🔴 **Neu entdeckter Bug: Empty Slots ignorieren User-Eingaben** - FIXED ✅
|
||||
|
||||
### Problem
|
||||
`should_sync_to_espocrm()` schaute nur auf Slot-Marker, nicht ob `tlf` wirklich leer ist.
|
||||
|
||||
**Konkretes Beispiel (Entity 104860)**:
|
||||
```python
|
||||
# Advoware Kommunikation:
|
||||
{
|
||||
"tlf": "23423", # User hat Wert eingetragen!
|
||||
"bemerkung": "[ESPOCRM-SLOT:1]" # Aber Slot-Marker noch vorhanden
|
||||
}
|
||||
|
||||
# should_sync_to_espocrm() returned: False ❌
|
||||
# → User-Eingabe wurde IGNORIERT!
|
||||
```
|
||||
|
||||
### Fix
|
||||
|
||||
#### 1. should_sync_to_espocrm()
|
||||
```python
|
||||
# Vorher:
|
||||
def should_sync_to_espocrm(advo_komm: Dict) -> bool:
|
||||
tlf = (advo_komm.get('tlf') or '').strip()
|
||||
if not tlf:
|
||||
return False
|
||||
|
||||
marker = parse_marker(bemerkung)
|
||||
if marker and marker['is_slot']:
|
||||
return False # ❌ Falsch! tlf könnte nicht leer sein!
|
||||
|
||||
return True
|
||||
|
||||
# Nachher:
|
||||
def should_sync_to_espocrm(advo_komm: Dict) -> bool:
|
||||
tlf = (advo_komm.get('tlf') or '').strip()
|
||||
|
||||
# Einziges Kriterium: Hat tlf einen Wert?
|
||||
return bool(tlf)
|
||||
```
|
||||
|
||||
#### 2. find_empty_slot()
|
||||
```python
|
||||
# Kommentar verdeutlicht:
|
||||
def find_empty_slot(kommkz: int, advo_kommunikationen: List[Dict]) -> Optional[Dict]:
|
||||
"""
|
||||
WICHTIG: User könnte Wert in einen Slot eingetragen haben
|
||||
→ dann ist es KEIN Empty Slot mehr!
|
||||
"""
|
||||
for k in advo_kommunikationen:
|
||||
tlf = (k.get('tlf') or '').strip()
|
||||
|
||||
# Muss BEIDES erfüllen: tlf leer UND Slot-Marker
|
||||
if not tlf:
|
||||
marker = parse_marker(bemerkung)
|
||||
if marker and marker.get('is_slot') and marker.get('kommKz') == kommkz:
|
||||
return k
|
||||
```
|
||||
|
||||
### Impact
|
||||
- ✅ User-Eingaben in "Slots" werden jetzt erkannt und synchronisiert (Var4)
|
||||
- ✅ Marker wird von `[ESPOCRM-SLOT:X]` zu `[ESPOCRM:base64:X]` aktualisiert
|
||||
- ✅ Keine verlorenen Daten mehr wenn User in Advoware etwas einträgt
|
||||
|
||||
---
|
||||
|
||||
## 🔴 **Zusätzlicher Bug: Konflikt-Handling unvollständig** - FIXED ✅
|
||||
|
||||
### Problem
|
||||
Bei Konflikt (`espo_wins=True`) wurde Advoware→EspoCRM korrekt übersprungen, ABER:
|
||||
- Var4-Einträge (neu in Advoware) blieben in Advoware
|
||||
- Sie wurden weder zu EspoCRM synchronisiert noch aus Advoware entfernt
|
||||
- Resultat: **Beide Systeme nicht identisch!**
|
||||
|
||||
**Konkretes Beispiel (Entity 104860 Trace)**:
|
||||
```
|
||||
[KOMM] ➕ Var4: New in Advoware - value='23423...', komm_id=149342
|
||||
[KOMM] ➕ Var4: New in Advoware - value='1231211111...', komm_id=149343
|
||||
[KOMM] ➕ Var4: New in Advoware - value='2342342423...', komm_id=149350
|
||||
[KOMM] ⚠️ CONFLICT: EspoCRM wins - skipping Advoware→EspoCRM sync
|
||||
[KOMM] ✅ Bidirectional Sync complete: 0 total changes ← FALSCH!
|
||||
```
|
||||
|
||||
→ Die 3 Einträge blieben in Advoware aber nicht in EspoCRM!
|
||||
|
||||
### Fix
|
||||
|
||||
#### 1. Var4-Einträge zu Empty Slots bei Konflikt
|
||||
```python
|
||||
# kommunikation_sync_utils.py:
|
||||
|
||||
elif direction in ['both', 'to_espocrm'] and espo_wins:
|
||||
self.logger.info(f"[KOMM] ⚠️ CONFLICT: EspoCRM wins - skipping Advoware→EspoCRM sync")
|
||||
|
||||
# FIX: Bei Konflikt müssen Var4-Einträge zu Empty Slots gemacht werden!
|
||||
self.logger.info(f"[KOMM] 🔄 Converting {len(diff['advo_new'])} Var4 entries to Empty Slots...")
|
||||
for komm in diff['advo_new']:
|
||||
await self._create_empty_slot(betnr, komm)
|
||||
result['espocrm_to_advoware']['deleted'] += 1
|
||||
```
|
||||
|
||||
#### 2. _create_empty_slot() erweitert für Var4
|
||||
```python
|
||||
async def _create_empty_slot(self, betnr: int, advo_komm: Dict) -> None:
|
||||
"""
|
||||
Verwendet für:
|
||||
- Var2: In EspoCRM gelöscht (hat Marker)
|
||||
- Var4 bei Konflikt: Neu in Advoware aber EspoCRM wins (hat KEINEN Marker)
|
||||
"""
|
||||
komm_id = advo_komm['id']
|
||||
tlf = (advo_komm.get('tlf') or '').strip()
|
||||
bemerkung = advo_komm.get('bemerkung') or ''
|
||||
marker = parse_marker(bemerkung)
|
||||
|
||||
# Bestimme kommKz
|
||||
if marker:
|
||||
kommkz = marker['kommKz'] # Var2: Hat Marker
|
||||
else:
|
||||
# Var4: Kein Marker - erkenne kommKz aus Wert
|
||||
kommkz = detect_kommkz(tlf) if tlf else 1
|
||||
|
||||
slot_marker = create_slot_marker(kommkz)
|
||||
|
||||
await self.advoware.update_kommunikation(betnr, komm_id, {
|
||||
'tlf': '',
|
||||
'bemerkung': slot_marker,
|
||||
'online': False
|
||||
})
|
||||
```
|
||||
|
||||
### Impact
|
||||
- ✅ Bei Konflikt werden Var4-Einträge jetzt zu Empty Slots gemacht
|
||||
- ✅ Beide Systeme sind nach Konflikt-Auflösung identisch
|
||||
- ✅ User sieht korrekte `total_changes` Count (nicht mehr 0)
|
||||
- ✅ Log zeigt: "Converting 3 Var4 entries to Empty Slots (EspoCRM wins)"
|
||||
|
||||
### Beispiel Trace (nach Fix)
|
||||
```
|
||||
[KOMM] ➕ Var4: New in Advoware - value='23423...', komm_id=149342
|
||||
[KOMM] ➕ Var4: New in Advoware - value='1231211111...', komm_id=149343
|
||||
[KOMM] ➕ Var4: New in Advoware - value='2342342423...', komm_id=149350
|
||||
[KOMM] ⚠️ CONFLICT: EspoCRM wins - skipping Advoware→EspoCRM sync
|
||||
[KOMM] 🔄 Converting 3 Var4 entries to Empty Slots (EspoCRM wins)...
|
||||
[KOMM] ✅ Created empty slot: komm_id=149342, kommKz=1
|
||||
[KOMM] ✅ Created empty slot: komm_id=149343, kommKz=1
|
||||
[KOMM] ✅ Created empty slot: komm_id=149350, kommKz=6
|
||||
[KOMM] ✅ Bidirectional Sync complete: 3 total changes ← KORREKT!
|
||||
```
|
||||
|
||||
---
|
||||
|
||||
## Zusammenfassung
|
||||
|
||||
### Geänderte Dateien
|
||||
1. ✅ `services/kommunikation_mapper.py`
|
||||
- `should_sync_to_espocrm()` - vereinfacht, nur tlf-Check
|
||||
- `find_empty_slot()` - Kommentar verdeutlicht
|
||||
|
||||
2. ✅ `services/beteiligte_sync_utils.py`
|
||||
- `compare_entities()` - Initial Sync Timestamp-Vergleich (Problem #11)
|
||||
- `release_sync_lock()` - Exponential backoff & Auto-Reset (Problem #12)
|
||||
- `validate_sync_result()` - NEU: Round-Trip Validation (Problem #13)
|
||||
|
||||
3. ✅ `services/kommunikation_sync_utils.py`
|
||||
- `sync_bidirectional()` - Hash nur für sync-relevante (Problem #3)
|
||||
- `sync_bidirectional()` - Var4→Empty Slots bei Konflikt (Zusätzlicher Bug)
|
||||
- `_compute_diff()` - Hash nur für sync-relevante (Problem #3)
|
||||
- `_create_empty_slot()` - Unterstützt jetzt Var4 ohne Marker (Zusätzlicher Bug)
|
||||
|
||||
4. ✅ `steps/vmh/beteiligte_sync_event_step.py`
|
||||
- `handler()` - Retry-Backoff Check (Problem #12)
|
||||
- `handle_update()` - Validation nach jedem Sync (Problem #13)
|
||||
|
||||
5. ✅ `steps/vmh/beteiligte_sync_cron_step.py`
|
||||
- `handler()` - Auto-Reset für permanently_failed (Problem #12)
|
||||
|
||||
### Neue EspoCRM Felder erforderlich
|
||||
|
||||
Folgende Felder müssen zu CBeteiligte Entity hinzugefügt werden:
|
||||
|
||||
```json
|
||||
{
|
||||
"syncNextRetry": {
|
||||
"type": "datetime",
|
||||
"notNull": false,
|
||||
"tooltip": "Nächster Retry-Zeitpunkt bei Exponential Backoff"
|
||||
},
|
||||
"syncAutoResetAt": {
|
||||
"type": "datetime",
|
||||
"notNull": false,
|
||||
"tooltip": "Auto-Reset Zeitpunkt für permanently_failed Entities"
|
||||
}
|
||||
}
|
||||
```
|
||||
|
||||
### Testing-Empfehlungen
|
||||
|
||||
1. **Initial Sync**: Teste mit existierender Advoware Entity die neuer als EspoCRM ist
|
||||
2. **Retry Backoff**: Trigger einen Fehler und beobachte steigende Retry-Zeiten
|
||||
3. **Auto-Reset**: Setze `syncAutoResetAt` auf Vergangenheit und prüfe Cron
|
||||
4. **Validation**: Manuell Advoware-Feld read-only machen und Sync auslösen
|
||||
5. **User-Eingabe in Slots**: Trage Wert in Advoware Kommunikation mit Slot-Marker ein
|
||||
|
||||
### Monitoring
|
||||
|
||||
Beobachte folgende Metriken nach Deployment:
|
||||
- Anzahl `permanently_failed` Entities (sollte sinken)
|
||||
- Anzahl `failed` Entities mit hohem `syncRetryCount`
|
||||
- Validation failures in Logs
|
||||
- Auto-Reset Aktivitäten im Cron
|
||||
|
||||
---
|
||||
|
||||
**Status**: ✅ Alle Fixes implementiert und validiert
|
||||
**Code Validation**: ✅ Alle 5 Dateien ohne Fehler
|
||||
**Nächste Schritte**: EspoCRM Felder hinzufügen, Testing, Deployment
|
||||
Reference in New Issue
Block a user