Soft1 Web Services errors

[Ioannis Gkouziotis]

Καλησπέρα σας,

Υπάρχει μια διεπαφή και μια επικοινωνία ενός 3rd party προγράμματος με το Soft1 μέσω Web Services. Το 3rd party, εκτελεί κάποια setData κάθε μέρα τα οποία μπορεί να είναι απο 0 μέχρι κάποιες εκατοντάδες. Όχι τρομερά πράγματα, παραστατικά αγορών κατά κύριο λόγο. Επίσης τραβάει τους προμηθευτές κάθε τόσο και ενημερώνει τη δική του βάση. Δεν ξέρω αν συνέβαινε απο πάντα, πρόσφατα με ενημέρωσαν ότι υπάρχει το εξής πρόβλημα. Όταν στέλνει κλήσεις setData, επιστρέφει 503 την πρώτη φορά, αμέσως μετά επιστρέφει 404 και την τρίτη διαδοχική φορά θα στείλει κανονικά. Το ίδιο μπορεί να συμβεί ανα πάσα ώρα και στιγμή μέσα στη μέρα χωρίς κάποιο προφανή λόγο, είναι random. Ενημέρωσα τη Soft1 και η απάντηση τους ήταν η εξής

Μην τρέχεις τον cloud agent σαν service, εκτέλεσέ το σαν webfeed ως εξής:

Από το server,  σε ένα εικονίδιο του Xplorer.exe βάζεις τις εξής παραμέτρους /webfeed:<το_serial_number_σου> /loglevel:2

Με το loglevel 2 δημιουργείται αρχείο σφαλμάτων που θα σου πει τι είναι αυτό που παράγει τα μηνύματα.

Όταν κάνω το παραπάνω, μου επιστρέφει ένα error στο Event Viewer 

XDllMain (Killing): '02xxxxxxxxxxxxxxxxxx' is not a valid integer value.

Προφανώς δεν αναγνωρίζει το σειριακό γιατί περιμένει integer και ο σειριακός ξεκινάει με 0.

Στο 2nd level support που με πήραν τηλέφωνο, καταλήξανε ότι 

Το πρόβλημα φαίνεται να οφείλεται στο γεγονός ότι πέφτει ο agent.

Οι πιθανοί λόγοι μπορεί να είναι είτε αποσυνδέσεις δικτύου είτε πρόβλημα σε κάποια άλλη υπηρεσία που εκτελείται παράλληλα.

Για να αποκλείσουμε το ενδεχόμενο να ευθύνεται κάποια υπηρεσία, θα χρειαστεί να διακόψετε ελεγχόμενα, μία-μία, τις υπόλοιπες υπηρεσίες (π.χ. site, γέφυρες με τρίτες εφαρμογές), ώστε να επιβεβαιώσουμε αν το πρόβλημα προέρχεται από κάποια συγκεκριμένη υπηρεσία.

Εχει συμβεί κάτι αντίστοιχο σε κάποιον άλλο ώστε να δω απο που να ξεκινήσω να το ψάχνω; Σε ότι αφορά την εγκατάσταση είναι σε Windows Server VM που τρέχει μόνο ο SQL Server, ο Licence Manager και ο Application Server μόνο χωρίς τίποτα άλλο. Δικτυακά, υπάρχει σύνδεση Starlink με Ubiquiti εξοπλισμό.

[bill.va...@gmail.com]

Καλησπέρα σας,

ο CloudAgent (Open Enterprise Engine) στις on premise εγκαταστάσεις εκτελείται ως service στα windows στον server της εγκατάστασης του πελάτη.

Για την ενεργοποίηση του log της καταγραφής (softone.log) που αφορά τα Web Services θα πρέπει στον φάκελο εγκατάστασης του Soft1 εκεί από όπου εκτελείται ο CloudAgent να δημιουργηθεί το αρχείο PARAMS.CFG το οποίο θα πρέπει να περιέχει τα ακόλουθα:

[PARAMS]

LOGLEVEL:1

Εκτός από το softone.log ενεργοποιείται αυτόματα και το XIOCP.log στο οποίο καταγράφονται οι προσπάθειες επανασύνδεσης στις Web Υπηρεσίες.

Παρακαλώ ενεργοποιείστε το service του CloudAgent, όπως αναφέρετε στο ακόλουθο link: https://wiki.soft1.eu/space/EMG/186876009/Open+Enterprise+Engine καθώς επίσης και το softone.log.

Τέλος, θα πρέπει να γίνει έλεγχος τόσο του softone.log όσο και του XIOCP.log για τον εντοπισμό του θέματος.

[Ioannis Gkouziotis]

Στο αρχείο PARAMS.CFG υπάρχει όντως το LOGLEVEL:1 και αντίστοιχα το αρχείο XIOCP.log. Ενδεικτικά στέλνω κάποιες γραμμές απο το softone.log και το XIOCP.log

XIOCP.log

2026-01-29 12:27:55: S1Agent - Softone Terminated. ExitCode: -1073740286

2026-01-29 12:27:56: Xplorer - Connected to Softone Server [onprem0.s1cloud.net]

2026-01-29 12:30:25: Xplorer - Reconnected After 0 secs

2026-01-29 12:32:55: Xplorer - Reconnected After 0 secs

2026-01-29 12:35:45: Xplorer - Reconnected After 0 secs

2026-01-29 12:37:45: Xplorer - Reconnected After 0 secs

2026-01-29 12:40:05: Xplorer - Reconnected After 0 secs

2026-01-29 12:43:05: Xplorer - Reconnected After 0 secs

2026-01-29 12:45:15: Xplorer - Reconnected After 0 secs

2026-01-29 12:47:35: Xplorer - Reconnected After 0 secs

2026-01-29 12:49:35: Xplorer - Reconnected After 0 secs

2026-01-29 12:51:35: Xplorer - Reconnected After 0 secs

2026-01-29 12:53:45: Xplorer - Reconnected After 0 secs

2026-01-29 12:55:45: Xplorer - Reconnected After 0 secs

2026-01-29 12:58:45: Xplorer - Reconnected After 0 secs

2026-01-29 13:00:45: Xplorer - Reconnected After 0 secs

2026-01-29 13:02:45: Xplorer - Reconnected After 0 secs

2026-01-29 13:06:35: Xplorer - Reconnected After 0 secs

2026-01-29 13:08:35: Xplorer - Reconnected After 0 secs

2026-01-29 13:11:25: Xplorer - Reconnected After 0 secs

2026-01-29 13:13:45: Xplorer - Reconnected After 0 secs

2026-01-29 13:15:45: Xplorer - Reconnected After 0 secs

2026-01-29 13:18:25: Xplorer - Reconnected After 0 secs

2026-01-29 13:20:25: Xplorer - Reconnected After 0 secs

2026-01-29 13:22:45: Xplorer - Reconnected After 0 secs

2026-01-29 13:25:05: Xplorer - Reconnected After 0 secs

2026-01-29 13:27:45: Xplorer - Reconnected After 0 secs

2026-01-29 13:31:25: Xplorer - Reconnected After 0 secs

2026-01-29 13:33:35: Xplorer - Reconnected After 0 secs

softone.log

2026-01-29 13:12:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:3, Active:1, Use:0, Back:0, LastUse:39531 ms, Requests:198  [198 92 Trs - 231 MB - 654 H - 1 %]

2026-01-29 13:12:56*  BAM TimerCalls: 45, Total Web Requests: 198, BAM Web Requests: 46, Total Steps: 15, BAM Current Web Requests : 2, Current Steps: 0 ParrallelExecutions: 0

2026-01-29 13:13:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:3, Active:1, Use:0, Back:0, LastUse:39515 ms, Requests:199  [199 92 Trs - 231 MB - 654 H - 3 %]

2026-01-29 13:14:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:3, Active:1, Use:0, Back:0, LastUse:39531 ms, Requests:200  [200 92 Trs - 230 MB - 656 H - 7 %]

2026-01-29 13:15:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:3, Active:1, Use:0, Back:0, LastUse:39531 ms, Requests:201  [201 92 Trs - 230 MB - 656 H - 4 %]

2026-01-29 13:15:56*  BAM TimerCalls: 48, Total Web Requests: 201, BAM Web Requests: 49, Total Steps: 15, BAM Current Web Requests : 2, Current Steps: 0 ParrallelExecutions: 0

2026-01-29 13:16:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:3, Active:2, Use:0, Back:0, LastUse:39531 ms, Requests:204  [204 93 Trs - 230 MB - 656 H - 30 %]

2026-01-29 13:17:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:3, Active:1, Use:0, Back:0, LastUse:39531 ms, Requests:205  [205 93 Trs - 230 MB - 656 H - 1 %]

2026-01-29 13:18:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:2, Active:1, Use:0, Back:0, LastUse:39531 ms, Requests:206  [206 93 Trs - 230 MB - 627 H - 0 %]

2026-01-29 13:18:55* [web.xco48111000-064A2E90] Destroying Support ---- Unused for 647 secs.

2026-01-29 13:18:56*  BAM TimerCalls: 51, Total Web Requests: 206, BAM Web Requests: 52, Total Steps: 15, BAM Current Web Requests : 2, Current Steps: 0 ParrallelExecutions: 0

2026-01-29 13:19:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:2, Active:1, Use:0, Back:0, LastUse:39531 ms, Requests:207  [207 93 Trs - 226 MB - 627 H - 0 %]

2026-01-29 13:20:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:2, Active:1, Use:0, Back:0, LastUse:39531 ms, Requests:209  [209 93 Trs - 226 MB - 625 H - 0 %]

2026-01-29 13:21:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:2, Active:1, Use:0, Back:0, LastUse:39547 ms, Requests:210  [210 93 Trs - 226 MB - 625 H - 1 %]

2026-01-29 13:21:56*  BAM TimerCalls: 54, Total Web Requests: 210, BAM Web Requests: 55, Total Steps: 15, BAM Current Web Requests : 2, Current Steps: 0 ParrallelExecutions: 0

2026-01-29 13:22:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:2, Active:2, Use:0, Back:0, LastUse:328 ms, Requests:216  [216 98 Trs - 227 MB - 636 H - 1 %]

2026-01-29 13:23:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:2, Active:2, Use:0, Back:0, LastUse:39531 ms, Requests:222  [222 102 Trs - 226 MB - 636 H - 1 %]

2026-01-29 13:24:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:2, Active:1, Use:0, Back:0, LastUse:39531 ms, Requests:223  [223 102 Trs - 226 MB - 631 H - 0 %]

2026-01-29 13:24:56*  BAM TimerCalls: 57, Total Web Requests: 223, BAM Web Requests: 58, Total Steps: 15, BAM Current Web Requests : 2, Current Steps: 0 ParrallelExecutions: 0

2026-01-29 13:25:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:2, Active:1, Use:0, Back:0, LastUse:39531 ms, Requests:225  [225 102 Trs - 226 MB - 631 H - 1 %]

2026-01-29 13:25:56* [WEB.XCO1000-028DA640] Creating Support (3) ---- Time: 328 ms QCount: 13 QTime: 141

2026-01-29 13:26:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:3, Active:2, Use:0, Back:0, LastUse:39515 ms, Requests:226  [226 102 Trs - 226 MB - 645 H - 1 %]

2026-01-29 13:27:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:3, Active:2, Use:0, Back:0, LastUse:39531 ms, Requests:227  [227 102 Trs - 226 MB - 646 H - 0 %]

2026-01-29 13:27:56*  BAM TimerCalls: 60, Total Web Requests: 227, BAM Web Requests: 61, Total Steps: 21, BAM Current Web Requests : 2, Current Steps: 6 ParrallelExecutions: 0

2026-01-29 13:28:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:3, Active:2, Use:0, Back:0, LastUse:18062 ms, Requests:233  [233 108 Trs - 227 MB - 659 H - 6 %]

2026-01-29 13:29:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:3, Active:1, Use:0, Back:0, LastUse:39531 ms, Requests:235  [235 108 Trs - 226 MB - 638 H - 15 %]

2026-01-29 13:30:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:3, Active:1, Use:0, Back:0, LastUse:39531 ms, Requests:236  [236 108 Trs - 226 MB - 638 H - 5 %]

2026-01-29 13:30:56*  BAM TimerCalls: 63, Total Web Requests: 236, BAM Web Requests: 64, Total Steps: 21, BAM Current Web Requests : 2, Current Steps: 0 ParrallelExecutions: 0

2026-01-29 13:31:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:3, Active:2, Use:0, Back:0, LastUse:21218 ms, Requests:240  [240 111 Trs - 227 MB - 638 H - 27 %]

2026-01-29 13:32:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:3, Active:1, Use:0, Back:0, LastUse:39531 ms, Requests:241  [241 111 Trs - 227 MB - 638 H - 14 %]

2026-01-29 13:33:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:3, Active:1, Use:0, Back:0, LastUse:39531 ms, Requests:243  [243 111 Trs - 227 MB - 638 H - 11 %]

2026-01-29 13:34:21* [web.xco0-0BDC8CD0] Creating Support (4) ---- Time: 360 ms QCount: 13 QTime: 204

2026-01-29 13:34:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:4, Active:2, Use:0, Back:0, LastUse:843 ms, Requests:264  [264 111 Trs - 227 MB - 652 H - 30 %]

2026-01-29 13:35:17* [web.xco1000-0BDCF760] Creating Support (5) ---- Time: 391 ms QCount: 13 QTime: 188

2026-01-29 13:35:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:5, Active:3, Use:0, Back:0, LastUse:38203 ms, Requests:290  [290 111 Trs - 227 MB - 666 H - 23 %]

2026-01-29 13:36:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:5, Active:1, Use:0, Back:0, LastUse:39531 ms, Requests:307  [307 111 Trs - 227 MB - 665 H - 23 %]

2026-01-29 13:37:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:4, Active:2, Use:0, Back:0, LastUse:39531 ms, Requests:316  [316 116 Trs - 228 MB - 672 H - 18 %]

2026-01-29 13:37:55* [WEB.XCO1000-028DA640] Destroying Support ---- Unused for 658 secs.

[bill.va...@gmail.com]

Στο XIOCP.log εχει καταγραφεί: 

2026-01-29 12:27:55: S1Agent - Softone Terminated. ExitCode: -1073740286

Στο softone.log τί έχει καταγράψει εκείνη την χρονική στιγμή;  

[Ioannis Gkouziotis]

2026-01-29 12:20:27* FeederInfo:ERPSERVER, sno:site, pId:4520, Count:1, Active:1, Use:0, Back:0, LastUse:39484 ms, Requests:41  [41 0 Trs - 95 MB - 460 H - 6 %]

2026-01-29 12:21:27* FeederInfo:ERPSERVER, sno:site, pId:4520, Count:1, Active:1, Use:0, Back:0, LastUse:39484 ms, Requests:42  [42 0 Trs - 95 MB - 460 H - 0 %]

2026-01-29 12:21:28*  BAM TimerCalls: 33, Total Web Requests: 42, BAM Web Requests: 33, Total Steps: 5, BAM Current Web Requests : 2, Current Steps: 0 ParrallelExecutions: 0

2026-01-29 12:22:27* FeederInfo:ERPSERVER, sno:site, pId:4520, Count:1, Active:1, Use:0, Back:0, LastUse:39484 ms, Requests:43  [43 0 Trs - 95 MB - 458 H - 0 %]

2026-01-29 12:23:27* FeederInfo:ERPSERVER, sno:site, pId:4520, Count:1, Active:1, Use:0, Back:0, LastUse:39484 ms, Requests:45  [45 0 Trs - 95 MB - 460 H - 0 %]

2026-01-29 12:24:27* FeederInfo:ERPSERVER, sno:site, pId:4520, Count:1, Active:1, Use:0, Back:0, LastUse:39484 ms, Requests:46  [46 0 Trs - 95 MB - 460 H - 0 %]

2026-01-29 12:24:28*  BAM TimerCalls: 36, Total Web Requests: 46, BAM Web Requests: 36, Total Steps: 5, BAM Current Web Requests : 2, Current Steps: 0 ParrallelExecutions: 0

2026-01-29 12:25:27* FeederInfo:ERPSERVER, sno:site, pId:4520, Count:1, Active:1, Use:0, Back:0, LastUse:39484 ms, Requests:47  [47 0 Trs - 95 MB - 460 H - 8 %]

2026-01-29 12:25:28* [WEB.XCO1000-03235050] Creating Support (2) ---- Time: 281 ms QCount: 13 QTime: 93

2026-01-29 12:25:29* ***** EXCEPTION Access violation at address 6CCF66EE in module 'jscript9.dll'. Write of address 060BB8DC ON Critical BAM ERROR 1 for code : WEB, Info: ModuleName:SALDOC, RunID:0, Priority:0, StepCnt:0, ObjID:866432 ,StepNo:0, FlowNo:0, VarIn:, INBACKGROUND:1, company:1000, PUSER:502

2026-01-29 12:26:27* FeederInfo:ERPSERVER, sno:site, pId:4520, Count:2, Active:2, Use:0, Back:0, LastUse:39484 ms, Requests:48  [48 0 Trs - 97 MB - 485 H - 4 %]

2026-01-29 12:27:27* FeederInfo:ERPSERVER, sno:site, pId:4520, Count:2, Active:2, Use:0, Back:0, LastUse:39484 ms, Requests:49  [49 0 Trs - 99 MB - 497 H - 17 %]

2026-01-29 12:27:28*  BAM TimerCalls: 39, Total Web Requests: 50, BAM Web Requests: 39, Total Steps: 8, BAM Current Web Requests : 2, Current Steps: 3 ParrallelExecutions: 0

2026-01-29 12:27:51* [web.xco47831000-0323D660] Creating Support (3) ---- Time: 234 ms QCount: 13 QTime: 93

2026-01-29 12:27:56* [web.xco0-028D3BB0] Creating Support (1) ---- Time: 329 ms QCount: 15 QTime: 126 [0 0 Trs - 66 MB - 395 H - 0 %]

2026-01-29 12:27:56* === Xplorer starts Feeding. Version: 6.00.622.11586, MaxFileDate: 20251223-16:38

2026-01-29 12:28:02* [web.xco47831000-028D4970] Creating Support (2) ---- Time: 234 ms QCount: 13 QTime: 93

2026-01-29 12:28:16* [WEB.XCO0-0649F0B0] Creating Support (3) ---- Time: 313 ms QCount: 13 QTime: 188

2026-01-29 12:28:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:3, Active:3, Use:0, Back:0, LastUse:34578 ms, Requests:14  [14 13 Trs - 108 MB - 495 H - 14 %]

2026-01-29 12:29:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:3, Active:1, Use:0, Back:0, LastUse:39515 ms, Requests:15  [15 13 Trs - 108 MB - 495 H - 4 %]

2026-01-29 12:30:47* [web.xco0-0649FE70] Creating Support (4) ---- Time: 235 ms QCount: 13 QTime: 108 [18 13 Trs - 109 MB - 508 H - 5 %]

2026-01-29 12:30:55* FeederInfo:ERPSERVER, sno:site, pId:8748, Count:4, Active:3, Use:0, Back:0, LastUse:8687 ms, Requests:18

2026-01-29 12:30:56*  BAM TimerCalls: 3, Total Web Requests: 18, BAM Web Requests: 3, Total Steps: 0, BAM Current Web Requests : 3, Current Steps: 0 ParrallelExecutions: 0

Το μόνο που βλέπω είναι ότι 12:25 προέκυψε ένα EXCEPTION. 

[bill.va...@gmail.com]

Το συγκεκριμένο error πολύ πιθανόν προέρχεται από κάποιο custom javascript.

Ο πελάτης έχει σενάρια B.A.M.;

Θα σας πρότεινα να στείλετε το αίτημα στο support, ώστε να το εξετάσουμε.