Crash on failed http_post_async

[Ruel Tmeizeh]

Version: v0.11.0~dev-20230123163036-0b9cf7ba7af5

My action plans get executed 1st of month.

I had a crash, and going back in the log, I see several lines like this:

Mar 1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: Error executing accountless action *debit: nil account!
Mar 1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: Error executing accountless action *debit: nil account!

Then:

Mar 1 00:00:02 cgr CGRateS <Rapyd_CGRates_1> [1190636]: <EEs> Exporter <4c3ff2364b4499a8ae049ed2a300c865:01USERS:1users> could not export because err: <Post "http ://127.0.0.1:11444/cgr/account-debit?product=users": dial tcp 127.0.0.1:11444: connect: connection refused>
Mar 1 00:00:02 cgr CGRateS <Rapyd_CGRates_1> [1190636]: <EEs> Exporter <4c3ff2364b4499a8ae049ed2a300c865:03USERS:3users> could not export because err: <Post "http ://127.0.0.1:11444/cgr/account-debit?product=users": dial tcp 127.0.0.1:11444: connect: connection refused>
Mar 1 00:00:02 cgr cgr-engine[1190636]: panic: runtime error: invalid memory address or nil pointer dereference
Mar 1 00:00:02 cgr cgr-engine[1190636]: [signal SIGSEGV: segmentation violation code=0x1 addr=0xa0 pc=0x1745d39]
Mar 1 00:00:02 cgr cgr-engine[1190636]: goroutine 5576979 [running]:
Mar 1 00:00:02 cgr cgr-engine[1190636]: github.com/cgrates/cgrates/ees.AddFailedPost({0xc00090a7c0, 0x1f}, {0xc000a9f9c0, 0x36}, {0x0, 0x0}, {0x198bd20, 0xc0006eef78}, 0x0)
Mar 1 00:00:02 cgr cgr-engine[1190636]: #011/root/go/src/cgrates/ees/libcdre.go:66 +0xd9
Mar 1 00:00:02 cgr cgr-engine[1190636]: github.com/cgrates/cgrates/ees.ExportWithAttempts.func1()
Mar 1 00:00:02 cgr cgr-engine[1190636]: #011/root/go/src/cgrates/ees/ees.go:291 +0xf1
Mar 1 00:00:02 cgr cgr-engine[1190636]: github.com/cgrates/cgrates/ees.ExportWithAttempts({0x2373da0, 0xc000b6a240}, {0x198bd20, 0xc0006eef78}, {0x0, 0x0})
Mar 1 00:00:02 cgr cgr-engine[1190636]: #011/root/go/src/cgrates/ees/ees.go:326 +0x551
Mar 1 00:00:02 cgr cgr-engine[1190636]: created by github.com/cgrates/cgrates/ees.callURLAsync
Mar 1 00:00:02 cgr cgr-engine[1190636]: #011/root/go/src/cgrates/ees/libactions.go:86 +0x22e

So it looks like the POST failed and that caused a crash? Not sure if the "nil account" lines are related to that or not? If not, what do they mean?

Most of the debit actions I think were processed, but there was at least one debit that was logged in StorDB, but not actually processed, so I don't know if that was in process when the crash happened or what. The HTTP POST was expected to fail, as there is no service currently listening at that URL just yet (it's in development) but I assumed it would just timeout or something and move on, rather than crashing so that's why I went ahead and had it on some of the actions I have in place.

 

Here is an example of the actions I have that use http_post_async (this is the one referenced above as 4c3ff2364b4499a8ae049ed2a300c865:03USERS:3users):

{
  "id": null,
  "result": [
    {
      "Identifier": "*debit",
      "BalanceId": "",
      "BalanceUuid": "",
      "BalanceType": "*monetary",
      "Units": "225",
      "ExpiryTime": "*unlimited",
      "Filters": "",
      "TimingTags": "",
      "DestinationIds": "",
      "RatingSubject": "",
      "Categories": "",
      "SharedGroups": "",
      "BalanceWeight": "0",
      "ExtraParameters": "",
      "BalanceBlocker": "false",
      "BalanceDisabled": "false",
      "Weight": 0
    },
    {
      "Identifier": "*http_post_async",
      "BalanceId": "",
      "BalanceUuid": "",
      "BalanceType": "",
      "Units": "0",
      "ExpiryTime": "*unlimited",
      "Filters": "",
      "TimingTags": "",
      "DestinationIds": "",
      "RatingSubject": "",
      "Categories": "",
      "SharedGroups": "",
      "BalanceWeight": "0",

      "ExtraParameters": "http://127.0.0.1:11444/cgr/account-debit?product=users",
      "BalanceBlocker": "false",
      "BalanceDisabled": "false",
      "Weight": 0
    },
    {
      "Identifier": "*cdrlog",
      "BalanceId": "",
      "BalanceUuid": "",
      "BalanceType": "",
      "Units": "0",
      "ExpiryTime": "*unlimited",
      "Filters": "",
      "TimingTags": "",
      "DestinationIds": "",
      "RatingSubject": "",
      "Categories": "",
      "SharedGroups": "",
      "BalanceWeight": "0",
      "ExtraParameters": "{\"Category\":\"USER\",\"ExtraInfo\":\"Users: 3 for 225.00\"}",
      "BalanceBlocker": "false",
      "BalanceDisabled": "false",
      "Weight": 0
    },
    {
      "Identifier": "*log",
      "BalanceId": "",
      "BalanceUuid": "",
      "BalanceType": "",
      "Units": "0",
      "ExpiryTime": "*unlimited",
      "Filters": "",
      "TimingTags": "",
      "DestinationIds": "",
      "RatingSubject": "",
      "Categories": "",
      "SharedGroups": "",
      "BalanceWeight": "0",
      "ExtraParameters": "",
      "BalanceBlocker": "false",

     "BalanceDisabled": "false",
      "Weight": 0
    }
  ],
  "error": null
}

I can of course remove the POST action if that will solve this temporarily, but what worries me is later on when I do have that endpoint working for CGRateS to POST to, what if that service goes down or something temporarily---I wouldn't want CGRateS to crash on that.

Any input is appreciated. Thanks!

[Ionut Boangiu]

Hi Ruel,

You are right. It is not supposed to panic from failing the export. The issue is fixed now on the latest master. About the "Error executing accountless action *debit: nil account!" log that you've encountered, it's just a warning letting you know that you have configured a "*debit" action without specifying which account to debit.

Thanks again for the find,
Ionuț

--
You received this message because you are subscribed to the Google Groups "CGRateS" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cgrates+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/cgrates/c90751e2-f6d1-4bbe-83c5-472d9423aaf0n%40googlegroups.com.

[Ruel Tmeizeh]

Ok thanks Ionuț --- glad to hear the crash error is fixed. 

When you explain about the nil account error, that of course makes sense, but how could that be, seeing all my debit actions are part of actionplans? In other words these were automated actions done by the scheduler, rather than something I sent over the API. 

Is there a way I can get the logger to show which action triggered the nil account error, rather than just telling that it happened? There were a bunch of those lines, and I've never seen that error before, so not sure which action would be responsible.

[Ionut Boangiu]

Hi Ruel,

First of all, are you sure that scheduler is the one that tried to execute those actions? I'm asking because, most of the time if not always (assuming your log level is 6 or higher), the scheduler posts logs giving information related to the actions/tasks it is currently executing. The previous syslog output that you've shared was focusing on the panic, and since that should not be related to your current question anymore, could you please provide a more relevant one?

Thanks,
Ionuț

To view this discussion on the web visit https://groups.google.com/d/msgid/cgrates/443ac6d8-52b6-4433-b4a2-7cdc975d9611n%40googlegroups.com.

[Ruel Tmeizeh]

It appears to be the scheduler, since it was immediately when all my actionplans get processed (first day of month at midnight).

Syslog looks like this:

Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: <Scheduler> Scheduler queue length: 55
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: <Scheduler> Action: rapyd_voice:SEAT_SCHOOL_5
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: <Scheduler> Scheduler queue length: 55
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: <Scheduler> Action: rapyd_voice:MINUTES_SCHOOL_1000
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: <Scheduler> Scheduler queue length: 55
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: <Scheduler> Action: rapyd_voice:SEAT_SCHOOL_10
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: <Scheduler> Scheduler queue length: 55
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: <Scheduler> Action: rapyd_voice:SEAT_SCHOOL_30

Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: Error executing accountless action *debit: nil account!
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: Error executing accountless action *debit: nil account!
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: Error executing accountless action *debit: nil account!
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: Error executing accountless action *debit: nil account!
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: Error executing accountless action *debit: nil account!
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: Error executing accountless action *debit: nil account!
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: Error executing accountless action *debit: nil account!
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: Error executing accountless action *debit: nil account!
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: Error executing accountless action *debit: nil account!
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: Error executing accountless action *debit: nil account!
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: Error executing accountless action *debit: nil account!

Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: <Scheduler> Scheduler queue length: 55
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: <Scheduler> Action: rapyd_voice:MINUTES_SCHOOL_4000
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: <Scheduler> Scheduler queue length: 55
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: <Scheduler> Action: rapyd_voice:SEAT_SCHOOL_35
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: <Scheduler> Scheduler queue length: 55
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: <Scheduler> Action: rapyd_voice:MINUTES_SCHOOL_1000
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: <Scheduler> Scheduler queue length: 55
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: <Scheduler> Action: rapyd_voice:SEAT_SCHOOL_15
Mar  1 00:00:00 cgr CGRateS <Rapyd_CGRates_1> [1190636]: <Scheduler> Scheduler queue length: 55
......

These shown are some of my actionplans, but none of these actionplans shown are attached to accounts. The error lines don't have a subsystem next to them, so I'm assuming it is the scheduler, but not certain?

I have compiled and installed the latest master yesterday, so in a couple days when these fire again hopefully it works out better. I will update here if there is a problem. :)

[Ionut Boangiu]

Hi Ruel,

I understand from your message that all of your "*debit" actions are part of action plans, and none of these action plans are associated with any accounts. If that is the case, then the error you encountered is to be expected. The initial step of the "*debit" action is to verify if the passed account is nil or not. If it is, it directly returns the error you received ("nil account").

Thanks,
Ionuț

[Ruel Tmeizeh]

Ah ok I see. So in other words, the scheduler executes all defined action plans, even if they are not associated with any accounts. This is what I did not expect. But if that is the case the error of course makes perfect sense as you have said. Is there any problem with these "rogue" actions being performed?