Subsearch map command doesn't work

[slipinski]

I have a query that uses map and subsearch inside map command as below:

host="X" booking source="Y" Success
| dedup ID
| table ID
|
map maxsearches=10 search="search host="X" source="Y" $ID$
|
stats range(_time) as "booking time"|table ID "booking time""*

I'm trying to get ID field from main search and run map subsearch with variable ID field. In main search I'm looking for events with success and parse IDs. In subsearch i'm trying to eval time between first and last occurrence of ID field.
I expect to have results in table format like below:

ID "booking time"
3345 867.34
2245 665.7
etc.

but I failed.

What I'm doing wrong?
Thanks in advance.

[to4kawa]

| makeresults
| eval _raw="raw
2020-04-15 12:17:17,046 backend_7.2.15: INFO services/ConnectionManagerService(backend): \ncreations: \nupdates: \ncancellations: 1236363-1
2020-04-15 11:49:23,844 backend_7.2.15: INFO services/ConfigurationManagerService(backend): Successfully applied config for 10.51.128.132.1.90000/igmpPortConfig! (Config success!). New contributors: Set(book.1236363-1), removed contributors: Set(book.1235337-1).
2020-04-15 11:49:23,800 backend_7.2.15: INFO services/ConfigurationManagerService(backend): Successfully applied config for 10.51.128.142.SwitchingCore/openflowConfig! (Config success!). New contributors: Set(book.1236363-1), removed contributors: Set(book.1235337-1).
2020-04-15 11:49:23,753 backend_7.2.15: INFO services/ConfigurationManagerService(backend): ControlledVertexFSM@10.51.128.132.SwitchingCore/rpfPortConfig: New config retrieved by Root state with delay None, new contributors: Set(book.1236363-1), removed contributors: Set(book.1235337-1)
2020-04-15 11:49:23,751 backend_7.2.15: INFO services/ConfigurationManagerService(backend): ControlledVertexFSM@10.51.128.140.SwitchingCore/openflowConfig: New config retrieved by Root state with delay None, new contributors: Set(book.1236363-1), removed contributors: Set(book.1235337-1)
2020-04-15 11:49:23,749 backend_7.2.15: INFO services/ConfigurationManagerService(backend): ControlledVertexFSM@10.51.128.132.1.90000/igmpPortConfig: New config retrieved by Root state with delay None, new contributors: Set(book.1236363-1), removed contributors: Set(book.1235337-1)
2020-04-15 11:49:23,749 backend_7.2.15: INFO services/ConfigurationManagerService(backend): ControlledVertexFSM@10.51.128.142.SwitchingCore/openflowConfig: New config retrieved by Root state with delay None, new contributors: Set(book.1236363-1), removed contributors: Set(book.1235337-1)
2020-04-15 11:49:23,696 backend_7.2.15: INFO services/VirtualRoutingService(backend): Crosspoints changed: l78: 114 -> 35 (booking = 1236363-1)), l0: 114 -> 35 (booking = 1236363-1)), 
Show syntax highlighted
2020-04-15 11:49:23,686 backend_7.2.15: INFO services/RedundancyControllerService(backend): redctl-1236363-1: Controller is started for booking with gpid = 100:book.1236363-1
2020-04-15 11:49:23,680 backend_7.2.15: INFO services/PathManagerService(backend): Booking 1236363-1(p2mp_join): 10.51.128.80.1.90202 -> 10.51.128.75.1.1000203 Success
Show syntax highlighted
2020-04-15 11:49:23,541 backend_7.2.15: INFO services/PathManagerService(backend): Update service[1236363-1] (p2mp_join): <10.51.128.80.1.90202> => <10.51.128.75.1.1000203> 2020-04-15T11:49:23.538+02:00 -> 2038-01-19T04:14:07.000+01:00
2020-04-15 11:49:23,538 backend_7.2.15: INFO services/ConnectionManagerService(backend): \ncreations: 1236363\nupdates: \ncancellations: 1235337-1"
| multikv noheader=t
| rex "(?<ID>\d{7})"
| rex "(?<time>^.*?,\d{3})"
| eval _time=strptime(time,"%F %T,%3Q")
| rename COMMENT as "this is sample. from here, the logic"

| reverse
| streamstats count(eval(searchmatch("ConnectionManagerService"))) as session by ID
| stats range(_time) as duration by session ID

[slipinski]

@to4kawa Thank you for your help. I'm in your dept.
I'm using the query below to calculate booking time per connection and average time from desired time period.
| stats range(eval(if(searchmatch("ncreations:") OR searchmatch("Config success!"),_time,NULL))) as duration by id
| where id!=0
| stats avg(duration)

It works perfecty.
I also tried to estimate this by using bucket command
bucket _time span=1h | stats avg(duration)
but it failed, because I had used _time value in command range. I can't use also timechart avg(duration), because of the same reason.

I guess I have to bind timestamp to "id" . Am I right?

regards,
Szymon

[to4kawa]

| eval hours=strftime(_time,"%d-%H")
| eventstats range(eval(if(searchmatch("ncreations:") OR searchmatch("Config success!"),_time,NULL))) as duration by id
| where id!=0

It might depend on how you calculate the average.

[slipinski]

Perfect. You're amazing.

[slipinski]

Thank you! It works well here, but unfortunately it doesn't on live data. Probably because I provided you with only piece of data related to particular ID. I will try to tweak it.

[to4kawa]

use by clause in subsearch

[slipinski]

Do you mean
stats range(_time) as "booking time" by ID ?

[harishalipaka]

@slipinski

Yes do like that stats range(_time) as "booking time" by ID ?

or go with Join command Join Id

[to4kawa]

What's bookingID?
just ID isn't it?

...
| table ID "booking time"

this is your query.

[slipinski]

Thanks. It works fine with map search like below
map maxsearches=10 search="search host="X" source="Y" $ID$

but if I elaborate this query with more filters like

map maxsearches=10 search="search host=X" source="Y" ("\ncreations" OR "new contributors: Set(book.$ID$)") AND $ID$ NOT "\ncancellations:$ID$" "*

it doesn't. I works of course if running a separate search with static parameter instead of variable $ID$. Do I need any special characters as I'm using * as argument for "any" and "\" symbol in search?

[to4kawa]

strange query, isn't it?
If you provide sample logs, I make query.

[slipinski]

Yes, it is 🙂
I've created the query to compare time of first and last events (\ncreations and Config success) accordingly related to particular connection 1236363. I don't want to have ncancellations1236363 in this comparison, that's why I'm using "\ncancellations:$ID$ statement in the query

"2020-04-15 12:17:17,046 backend_7.2.15: INFO services/ConnectionManagerService(backend): \ncreations: \nupdates: \ncancellations: 1236363-1"
"2020-04-15 11:49:23,844 backend_7.2.15: INFO services/ConfigurationManagerService(backend): Successfully applied config for 10.51.128.132.1.90000/igmpPortConfig! (Config success!). New contributors: Set(book.1236363-1), removed contributors: Set(book.1235337-1)."
"2020-04-15 11:49:23,800 backend_7.2.15: INFO services/ConfigurationManagerService(backend): Successfully applied config for 10.51.128.142.SwitchingCore/openflowConfig! (Config success!). New contributors: Set(book.1236363-1), removed contributors: Set(book.1235337-1)."
"2020-04-15 11:49:23,753 backend_7.2.15: INFO services/ConfigurationManagerService(backend): ControlledVertexFSM@10.51.128.132.SwitchingCore/rpfPortConfig: New config retrieved by Root state with delay None, new contributors: Set(book.1236363-1), removed contributors: Set(book.1235337-1)"
"2020-04-15 11:49:23,751 backend_7.2.15: INFO services/ConfigurationManagerService(backend): ControlledVertexFSM@10.51.128.140.SwitchingCore/openflowConfig: New config retrieved by Root state with delay None, new contributors: Set(book.1236363-1), removed contributors: Set(book.1235337-1)"
"2020-04-15 11:49:23,749 backend_7.2.15: INFO services/ConfigurationManagerService(backend): ControlledVertexFSM@10.51.128.132.1.90000/igmpPortConfig: New config retrieved by Root state with delay None, new contributors: Set(book.1236363-1), removed contributors: Set(book.1235337-1)"
"2020-04-15 11:49:23,749 backend_7.2.15: INFO services/ConfigurationManagerService(backend): ControlledVertexFSM@10.51.128.142.SwitchingCore/openflowConfig: New config retrieved by Root state with delay None, new contributors: Set(book.1236363-1), removed contributors: Set(book.1235337-1)"
"2020-04-15 11:49:23,696 backend_7.2.15: INFO services/VirtualRoutingService(backend): Crosspoints changed: l78: 114 -> 35 (booking = 1236363-1)), l0: 114 -> 35 (booking = 1236363-1)), "
Show syntax highlighted
"2020-04-15 11:49:23,686 backend_7.2.15: INFO services/RedundancyControllerService(backend): redctl-1236363-1: Controller is started for booking with gpid = 100:book.1236363-1"
"2020-04-15 11:49:23,680 backend_7.2.15: INFO services/PathManagerService(backend): Booking 1236363-1(p2mp_join): 10.51.128.80.1.90202 -> 10.51.128.75.1.1000203 Success"
Show syntax highlighted
"2020-04-15 11:49:23,541 backend_7.2.15: INFO services/PathManagerService(backend): Update service1236363-1: <10.51.128.80.1.90202> => <10.51.128.75.1.1000203> 2020-04-15T11:49:23.538+02:00 -> 2038-01-19T04:14:07.000+01:00"
"2020-04-15 11:49:23,538 backend_7.2.15: INFO services/ConnectionManagerService(backend): \ncreations: 1236363\nupdates: \ncancellations: 1235337-1"